From bcd910cfe28eb237741e3bf25fc2c454206a1c30 Mon Sep 17 00:00:00 2001 From: Russ Cox Date: Wed, 19 Jan 2011 13:41:42 -0500 Subject: [PATCH] runtime: add per-pause gc stats R=r, r2 CC=golang-dev https://golang.org/cl/3980042 --- src/pkg/runtime/debug.go | 12 +++++----- src/pkg/runtime/malloc.h | 4 +++- src/pkg/runtime/mgc0.c | 5 ++++- test/garbage/Makefile | 4 ++-- test/garbage/parser.go | 48 +++++++++++++++++++++++++++++----------- test/garbage/peano.go | 4 +--- test/garbage/stats.go | 44 ++++++++++++++++++++++++++++++++++++ test/garbage/tree.go | 6 +---- 8 files changed, 97 insertions(+), 30 deletions(-) create mode 100644 test/garbage/stats.go diff --git a/src/pkg/runtime/debug.go b/src/pkg/runtime/debug.go index 3ce35cc5ba9..cf30374f098 100644 --- a/src/pkg/runtime/debug.go +++ b/src/pkg/runtime/debug.go @@ -39,6 +39,7 @@ type MemStatsType struct { Sys uint64 // bytes obtained from system (should be sum of XxxSys below) Lookups uint64 // number of pointer lookups Mallocs uint64 // number of mallocs + Frees uint64 // number of frees // Main allocation heap statistics. HeapAlloc uint64 // bytes allocated and still in use @@ -60,11 +61,12 @@ type MemStatsType struct { BuckHashSys uint64 // profiling bucket hash table // Garbage collector statistics. - NextGC uint64 - PauseNs uint64 - NumGC uint32 - EnableGC bool - DebugGC bool + NextGC uint64 + PauseTotalNs uint64 + PauseNs [256]uint64 // most recent GC pause times + NumGC uint32 + EnableGC bool + DebugGC bool // Per-size allocation statistics. // Not locked during update; approximate. diff --git a/src/pkg/runtime/malloc.h b/src/pkg/runtime/malloc.h index 0cee6c0ddb8..7e750b9170d 100644 --- a/src/pkg/runtime/malloc.h +++ b/src/pkg/runtime/malloc.h @@ -176,6 +176,7 @@ struct MStats uint64 sys; // bytes obtained from system (should be sum of xxx_sys below) uint64 nlookup; // number of pointer lookups uint64 nmalloc; // number of mallocs + uint64 nfree; // number of frees // Statistics about malloc heap. // protected by mheap.Lock @@ -199,7 +200,8 @@ struct MStats // Statistics about garbage collector. // Protected by stopping the world during GC. uint64 next_gc; // next GC (in heap_alloc time) - uint64 pause_ns; + uint64 pause_total_ns; + uint64 pause_ns[256]; uint32 numgc; bool enablegc; bool debuggc; diff --git a/src/pkg/runtime/mgc0.c b/src/pkg/runtime/mgc0.c index 6dcb61091da..4eace9f8312 100644 --- a/src/pkg/runtime/mgc0.c +++ b/src/pkg/runtime/mgc0.c @@ -210,6 +210,7 @@ sweepspan(MSpan *s) case RefNone: // Free large object. mstats.alloc -= s->npages<npages<npages< sizeof(uintptr)) ((uintptr*)p)[1] = 1; // mark as "needs to be zeroed" mstats.alloc -= size; + mstats.nfree++; mstats.by_size[s->sizeclass].nfree++; runtime·MCache_Free(c, p, s->sizeclass, size); break; @@ -381,7 +383,8 @@ runtime·gc(int32 force) t1 = runtime·nanotime(); mstats.numgc++; - mstats.pause_ns += t1 - t0; + mstats.pause_ns[mstats.numgc%nelem(mstats.pause_ns)] = t1 - t0; + mstats.pause_total_ns += t1 - t0; if(mstats.debuggc) runtime·printf("pause %D\n", t1-t0); runtime·semrelease(&gcsema); diff --git a/test/garbage/Makefile b/test/garbage/Makefile index ab29e0956c0..e8338438265 100644 --- a/test/garbage/Makefile +++ b/test/garbage/Makefile @@ -11,8 +11,8 @@ ALL=\ all: $(addsuffix .out, $(ALL)) -%.$O: %.go - $(GC) $*.go +%.$O: %.go stats.go + $(GC) $*.go stats.go %.out: %.$O $(LD) -o $@ $*.$O diff --git a/test/garbage/parser.go b/test/garbage/parser.go index cf68737fb2f..d8716dfb12d 100644 --- a/test/garbage/parser.go +++ b/test/garbage/parser.go @@ -11,13 +11,19 @@ import ( "fmt" "go/ast" "go/parser" + "go/token" "os" "path" "runtime" "strings" "time" + "http" + _ "http/pprof" + "log" ) +var serve = flag.String("serve", "", "serve http on this address at end") + func isGoFile(dir *os.FileInfo) bool { return dir.IsRegular() && !strings.HasPrefix(dir.Name, ".") && // ignore .files @@ -30,7 +36,7 @@ func isPkgFile(dir *os.FileInfo) bool { } func pkgName(filename string) string { - file, err := parser.ParseFile(filename, nil, parser.PackageClauseOnly) + file, err := parser.ParseFile(token.NewFileSet(), filename, nil, parser.PackageClauseOnly) if err != nil || file == nil { return "" } @@ -58,7 +64,7 @@ func parseDir(dirpath string) map[string]*ast.Package { } // get package AST - pkgs, err := parser.ParseDir(dirpath, filter, parser.ParseComments) + pkgs, err := parser.ParseDir(token.NewFileSet(), dirpath, filter, parser.ParseComments) if err != nil { println("parse", dirpath, err.String()) panic("fail") @@ -67,12 +73,19 @@ func parseDir(dirpath string) map[string]*ast.Package { } func main() { + runtime.GOMAXPROCS(4) + go func() {}() + go func() {}() + go func() {}() st := &runtime.MemStats + packages = append(packages, packages...) + packages = append(packages, packages...) n := flag.Int("n", 4, "iterations") p := flag.Int("p", len(packages), "# of packages to keep in memory") flag.BoolVar(&st.DebugGC, "d", st.DebugGC, "print GC debugging info (pause times)") flag.Parse() + var lastParsed []map[string]*ast.Package var t0 int64 pkgroot := runtime.GOROOT() + "/src/pkg/" for pass := 0; pass < 2; pass++ { @@ -81,7 +94,7 @@ func main() { // than the normal pauses and would otherwise make // the average look much better than it actually is. st.NumGC = 0 - st.PauseNs = 0 + st.PauseTotalNs = 0 t0 = time.Nanoseconds() for i := 0; i < *n; i++ { @@ -89,25 +102,34 @@ func main() { for j := range parsed { parsed[j] = parseDir(pkgroot + packages[j%len(packages)]) } + if i+1 == *n && *serve != "" { + lastParsed = parsed + } } runtime.GC() + runtime.GC() } t1 := time.Nanoseconds() fmt.Printf("Alloc=%d/%d Heap=%d Mallocs=%d PauseTime=%.3f/%d = %.3f\n", st.Alloc, st.TotalAlloc, st.Sys, - st.Mallocs, float64(st.PauseNs)/1e9, - st.NumGC, float64(st.PauseNs)/1e9/float64(st.NumGC)) - - fmt.Printf("%10s %10s %10s\n", "size", "#alloc", "#free") - for _, s := range st.BySize { - fmt.Printf("%10d %10d %10d\n", s.Size, s.Mallocs, s.Frees) - } + st.Mallocs, float64(st.PauseTotalNs)/1e9, + st.NumGC, float64(st.PauseTotalNs)/1e9/float64(st.NumGC)) + /* + fmt.Printf("%10s %10s %10s\n", "size", "#alloc", "#free") + for _, s := range st.BySize { + fmt.Printf("%10d %10d %10d\n", s.Size, s.Mallocs, s.Frees) + } + */ // Standard gotest benchmark output, collected by build dashboard. - fmt.Printf("garbage.BenchmarkParser %d %d ns/op\n", *n, (t1-t0)/int64(*n)) - fmt.Printf("garbage.BenchmarkParserPause %d %d ns/op\n", st.NumGC, int64(st.PauseNs)/int64(st.NumGC)) + gcstats("BenchmarkParser", *n, t1-t0) + + if *serve != "" { + log.Exit(http.ListenAndServe(*serve, nil)) + println(lastParsed) + } } @@ -183,7 +205,6 @@ var packages = []string{ "math", "mime", "net", - "nntp", "os", "os/signal", "patch", @@ -195,6 +216,7 @@ var packages = []string{ "runtime", "scanner", "sort", + "smtp", "strconv", "strings", "sync", diff --git a/test/garbage/peano.go b/test/garbage/peano.go index b026354e8c1..b4d31856126 100644 --- a/test/garbage/peano.go +++ b/test/garbage/peano.go @@ -123,7 +123,6 @@ func verify() { func main() { - st := &runtime.MemStats t0 := time.Nanoseconds() verify() for i := 0; i <= 9; i++ { @@ -132,6 +131,5 @@ func main() { runtime.GC() t1 := time.Nanoseconds() - fmt.Printf("garbage.BenchmarkPeano 1 %d ns/op\n", t1-t0) - fmt.Printf("garbage.BenchmarkPeanoPause %d %d ns/op\n", st.NumGC, int64(st.PauseNs)/int64(st.NumGC)) + gcstats("BenchmarkPeano", 1, t1-t0) } diff --git a/test/garbage/stats.go b/test/garbage/stats.go new file mode 100644 index 00000000000..474e6ad4abc --- /dev/null +++ b/test/garbage/stats.go @@ -0,0 +1,44 @@ +// Copyright 2010 The Go Authors. All rights reserved. +// Use of this source code is governed by a BSD-style +// license that can be found in the LICENSE file. + +package main + +import ( + "fmt" + "runtime" + "sort" +) + +func gcstats(name string, n int, t int64) { + st := &runtime.MemStats + fmt.Printf("garbage.%sMem Alloc=%d/%d Heap=%d NextGC=%d Mallocs=%d\n", name, st.Alloc, st.TotalAlloc, st.Sys, st.NextGC, st.Mallocs) + fmt.Printf("garbage.%s %d %d ns/op\n", name, n, t/int64(n)) + fmt.Printf("garbage.%sLastPause 1 %d ns/op\n", name, st.PauseNs[(st.NumGC-1)%uint32(len(st.PauseNs))]) + fmt.Printf("garbage.%sPause %d %d ns/op\n", name, st.NumGC, int64(st.PauseTotalNs)/int64(st.NumGC)) + nn := int(st.NumGC) + if nn >= len(st.PauseNs) { + nn = len(st.PauseNs) + } + t1, t2, t3, t4, t5 := tukey5(st.PauseNs[0:nn]) + fmt.Printf("garbage.%sPause5: %d %d %d %d %d\n", name, t1, t2, t3, t4, t5) + +// fmt.Printf("garbage.%sScan: %v\n", name, st.ScanDist) +} + +type T []uint64 +func (t T) Len() int { return len(t) } +func (t T) Swap(i, j int) { t[i], t[j] = t[j], t[i] } +func (t T) Less(i, j int) bool { return t[i] < t[j] } + +func tukey5(raw []uint64) (lo, q1, q2, q3, hi uint64) { + x := make(T, len(raw)) + copy(x, raw) + sort.Sort(T(x)) + lo = x[0] + q1 = x[len(x)/4] + q2 = x[len(x)/2] + q3 = x[len(x)*3/4] + hi = x[len(x)-1] + return +} diff --git a/test/garbage/tree.go b/test/garbage/tree.go index 816693fbebf..c5eae9760f2 100644 --- a/test/garbage/tree.go +++ b/test/garbage/tree.go @@ -39,7 +39,6 @@ package main import ( "flag" "fmt" - "runtime" "time" ) @@ -95,10 +94,7 @@ func main() { fmt.Printf("long lived tree of depth %d\t check: %d\n", maxDepth, longLivedTree.itemCheck()) t1 := time.Nanoseconds() - st := &runtime.MemStats // Standard gotest benchmark output, collected by build dashboard. - fmt.Printf("garbage.BenchmarkTree %d %d ns/op\n", *n, (t1-t0)/int64(*n)) - fmt.Printf("garbage.BenchmarkTreePause %d %d ns/op\n", st.NumGC, int64(st.PauseNs)/int64(st.NumGC)) - + gcstats("BenchmarkTree", *n, t1-t0) }