From: Russ Cox Date: Wed, 2 Mar 2016 17:32:38 +0000 (-0500) Subject: runtime/pprof: sort counted profiles by count X-Git-Tag: go1.7beta1~1603 X-Git-Url: http://www.git.cypherpunks.su/?a=commitdiff_plain;h=6969d9bf038deebefa556b90e7467b8636c16e91;p=gostls13.git runtime/pprof: sort counted profiles by count This is especially helpful in programs with very large numbers of goroutines: the bulk of the goroutines will show up at the top. Before: 1 @ 0x86ab8 0x86893 0x82164 0x8e7ce 0x7b798 0x5b871 # 0x86ab8 runtime/pprof.writeRuntimeProfile+0xb8 /Users/rsc/go/src/runtime/pprof/pprof.go:545 # 0x86893 runtime/pprof.writeGoroutine+0x93 /Users/rsc/go/src/runtime/pprof/pprof.go:507 # 0x82164 runtime/pprof.(*Profile).WriteTo+0xd4 /Users/rsc/go/src/runtime/pprof/pprof.go:236 # 0x8e7ce runtime/pprof_test.TestGoroutineCounts+0x15e /Users/rsc/go/src/runtime/pprof/pprof_test.go:603 # 0x7b798 testing.tRunner+0x98 /Users/rsc/go/src/testing/testing.go:473 1 @ 0x2d373 0x2d434 0x560f 0x516b 0x7cd42 0x7b861 0x2297 0x2cf90 0x5b871 # 0x7cd42 testing.RunTests+0x8d2 /Users/rsc/go/src/testing/testing.go:583 # 0x7b861 testing.(*M).Run+0x81 /Users/rsc/go/src/testing/testing.go:515 # 0x2297 main.main+0x117 runtime/pprof/_test/_testmain.go:72 # 0x2cf90 runtime.main+0x2b0 /Users/rsc/go/src/runtime/proc.go:188 10 @ 0x2d373 0x2d434 0x560f 0x516b 0x8e5b6 0x5b871 # 0x8e5b6 runtime/pprof_test.func1+0x36 /Users/rsc/go/src/runtime/pprof/pprof_test.go:582 50 @ 0x2d373 0x2d434 0x560f 0x516b 0x8e656 0x5b871 # 0x8e656 runtime/pprof_test.func3+0x36 /Users/rsc/go/src/runtime/pprof/pprof_test.go:584 40 @ 0x2d373 0x2d434 0x560f 0x516b 0x8e606 0x5b871 # 0x8e606 runtime/pprof_test.func2+0x36 /Users/rsc/go/src/runtime/pprof/pprof_test.go:583 After: 50 @ 0x2d373 0x2d434 0x560f 0x516b 0x8ecc6 0x5b871 # 0x8ecc6 runtime/pprof_test.func3+0x36 /Users/rsc/go/src/runtime/pprof/pprof_test.go:584 40 @ 0x2d373 0x2d434 0x560f 0x516b 0x8ec76 0x5b871 # 0x8ec76 runtime/pprof_test.func2+0x36 /Users/rsc/go/src/runtime/pprof/pprof_test.go:583 10 @ 0x2d373 0x2d434 0x560f 0x516b 0x8ec26 0x5b871 # 0x8ec26 runtime/pprof_test.func1+0x36 /Users/rsc/go/src/runtime/pprof/pprof_test.go:582 1 @ 0x2d373 0x2d434 0x560f 0x516b 0x7cd42 0x7b861 0x2297 0x2cf90 0x5b871 # 0x7cd42 testing.RunTests+0x8d2 /Users/rsc/go/src/testing/testing.go:583 # 0x7b861 testing.(*M).Run+0x81 /Users/rsc/go/src/testing/testing.go:515 # 0x2297 main.main+0x117 runtime/pprof/_test/_testmain.go:72 # 0x2cf90 runtime.main+0x2b0 /Users/rsc/go/src/runtime/proc.go:188 1 @ 0x87128 0x86f03 0x82164 0x8ee30 0x7b798 0x5b871 # 0x87128 runtime/pprof.writeRuntimeProfile+0xb8 /Users/rsc/go/src/runtime/pprof/pprof.go:566 # 0x86f03 runtime/pprof.writeGoroutine+0x93 /Users/rsc/go/src/runtime/pprof/pprof.go:528 # 0x82164 runtime/pprof.(*Profile).WriteTo+0xd4 /Users/rsc/go/src/runtime/pprof/pprof.go:236 # 0x8ee30 runtime/pprof_test.TestGoroutineCounts+0x150 /Users/rsc/go/src/runtime/pprof/pprof_test.go:603 # 0x7b798 testing.tRunner+0x98 /Users/rsc/go/src/testing/testing.go:473 Change-Id: I43de9eee2d96f9c46f7b0fbe099a0571164324f5 Reviewed-on: https://go-review.googlesource.com/20107 Reviewed-by: Ian Lance Taylor --- diff --git a/src/runtime/pprof/pprof.go b/src/runtime/pprof/pprof.go index b702fd345d..901467fa9a 100644 --- a/src/runtime/pprof/pprof.go +++ b/src/runtime/pprof/pprof.go @@ -296,22 +296,25 @@ func printCountProfile(w io.Writer, debug int, name string, p countProfile) erro } return buf.String() } - m := map[string]int{} + count := map[string]int{} + index := map[string]int{} + var keys []string n := p.Len() for i := 0; i < n; i++ { - m[key(p.Stack(i))]++ + k := key(p.Stack(i)) + if count[k] == 0 { + index[k] = i + keys = append(keys, k) + } + count[k]++ } - // Print stacks, listing count on first occurrence of a unique stack. - for i := 0; i < n; i++ { - stk := p.Stack(i) - s := key(stk) - if count := m[s]; count != 0 { - fmt.Fprintf(w, "%d %s\n", count, s) - if debug > 0 { - printStackRecord(w, stk, false) - } - delete(m, s) + sort.Sort(&keysByCount{keys, count}) + + for _, k := range keys { + fmt.Fprintf(w, "%d %s\n", count[k], k) + if debug > 0 { + printStackRecord(w, p.Stack(index[k]), false) } } @@ -321,6 +324,23 @@ func printCountProfile(w io.Writer, debug int, name string, p countProfile) erro return b.Flush() } +// keysByCount sorts keys with higher counts first, breaking ties by key string order. +type keysByCount struct { + keys []string + count map[string]int +} + +func (x *keysByCount) Len() int { return len(x.keys) } +func (x *keysByCount) Swap(i, j int) { x.keys[i], x.keys[j] = x.keys[j], x.keys[i] } +func (x *keysByCount) Less(i, j int) bool { + ki, kj := x.keys[i], x.keys[j] + ci, cj := x.count[ki], x.count[kj] + if ci != cj { + return ci > cj + } + return ki < kj +} + // printStackRecord prints the function + source line information // for a single stack trace. func printStackRecord(w io.Writer, stk []uintptr, allFrames bool) { diff --git a/src/runtime/pprof/pprof_test.go b/src/runtime/pprof/pprof_test.go index d232257c20..fa0af59b37 100644 --- a/src/runtime/pprof/pprof_test.go +++ b/src/runtime/pprof/pprof_test.go @@ -578,3 +578,47 @@ func blockCond() { c.Wait() mu.Unlock() } + +func func1(c chan int) { <-c } +func func2(c chan int) { <-c } +func func3(c chan int) { <-c } +func func4(c chan int) { <-c } + +func TestGoroutineCounts(t *testing.T) { + c := make(chan int) + for i := 0; i < 100; i++ { + if i%10 == 0 { + go func1(c) + continue + } + if i%2 == 0 { + go func2(c) + continue + } + go func3(c) + } + time.Sleep(10 * time.Millisecond) // let goroutines block on channel + + var w bytes.Buffer + Lookup("goroutine").WriteTo(&w, 1) + prof := w.String() + + if !containsInOrder(prof, "\n50 @ ", "\n40 @", "\n10 @", "\n1 @") { + t.Errorf("expected sorted goroutine counts:\n%s", prof) + } + + close(c) + + time.Sleep(10 * time.Millisecond) // let goroutines exit +} + +func containsInOrder(s string, all ...string) bool { + for _, t := range all { + i := strings.Index(s, t) + if i < 0 { + return false + } + s = s[i+len(t):] + } + return true +}