How to interpret a pprof output?

[Fatih Arslan]

I've profiled one of the methods in the set package:
https://github.com/fatih/set.
For the beginning I only tested the thread-safe Intersection() method with the
test written below (as a sidenote, as a Mac user I've already applied
this patch:
http://godoc.org/code.google.com/p/rsc/cmd/pprof_mac_fix):

func benchmark(b *testing.B, numberOfItems int) {
s := New()
u := New()

for i := 0; i < numberOfItems; i++ {
s.Add(i)
u.Add(i)
}

b.ResetTimer()
for i := 0; i < b.N; i++ {
s.Intersection(u)
}

}

func BenchmarkIntersection10(b *testing.B) {
benchmark(b, 10)
}

// same for 100, 1000, 10000 and 1000000

I've compiled it to a binary with "go test -v" and invoked the
following command:

./set.test -test.cpuprofile=set.prof -test.bench "Intersection"

The output for this command was:

PASS
BenchmarkIntersection10 500000 4574 ns/op
BenchmarkIntersection100 50000 40400 ns/op
BenchmarkIntersection1000 5000 467702 ns/op
BenchmarkIntersection10000 500 4323818 ns/op
BenchmarkIntersection100000 50 44394690 ns/op
BenchmarkIntersection1000000 2 715673797 ns/op

Using "go tool pprof set.test set.prof" command with "top20" gives me:

(pprof) top20
Total: 1488 samples
214 14.4% 14.4% 737 49.5% hash_insert
185 12.4% 26.8% 305 20.5% evacuate
170 11.4% 38.2% 170 11.4% scanblock
94 6.3% 44.6% 149 10.0% hash_remove
86 5.8% 50.3% 86 5.8% runtime.usleep
85 5.7% 56.0% 168 11.3% ifacehash1
83 5.6% 61.6% 83 5.6% runtime.aeshash64
81 5.4% 67.1% 81 5.4% hash_next
46 3.1% 70.2% 236 15.9% runtime.nilinterhash
35 2.4% 72.5% 35 2.4% runtime.markspan
31 2.1% 74.6% 38 2.6% runtime.mapiter1
26 1.7% 76.3% 772 51.9% runtime.mapassign1
25 1.7% 78.0% 130 8.7% _/Users/fatih/Code/set.(*set).List
25 1.7% 79.7% 25 1.7% sweepspan
23 1.5% 81.2% 23 1.5% runtime.memclr
22 1.5% 82.7% 190 12.8% runtime.efacehash
20 1.3% 84.1% 20 1.3% runtime.nilintercopy
13 0.9% 84.9% 13 0.9% stkbucket
12 0.8% 85.8% 898 60.3% runtime.mapassign
11 0.7% 86.5% 143 9.6% cnew

and "top20 -cum" gives me:

(pprof) top20 -cum
Total: 1488 samples
0 0.0% 0.0% 1183 79.5% runtime.gosched0
0 0.0% 0.0% 1183 79.5% testing.(*B).launch
0 0.0% 0.0% 1183 79.5% testing.(*B).runN
3 0.2% 0.2% 1182 79.4% _/Users/fatih/Code/set.benchmark
1 0.1% 0.3% 1066 71.6%
_/Users/fatih/Code/set.(*set).Intersection
12 0.8% 1.1% 898 60.3% runtime.mapassign
1 0.1% 1.1% 842 56.6% _/Users/fatih/Code/set.(*set).Copy
26 1.7% 2.9% 772 51.9% runtime.mapassign1
214 14.4% 17.3% 737 49.5% hash_insert
0 0.0% 17.3% 713 47.9% _/Users/fatih/Code/set.NewNonTS
9 0.6% 17.9% 696 46.8% _/Users/fatih/Code/set.(*set).Add
1 0.1% 17.9% 658 44.2%
_/Users/fatih/Code/set.(*set).Difference
8 0.5% 18.5% 313 21.0% grow_work
0 0.0% 18.5% 305 20.5% System
185 12.4% 30.9% 305 20.5% evacuate
0 0.0% 30.9% 277 18.6%
_/Users/fatih/Code/set.BenchmarkIntersection1000000
46 3.1% 34.0% 236 15.9% runtime.nilinterhash
0 0.0% 34.0% 222 14.9%
_/Users/fatih/Code/set.(*set).Separate
0 0.0% 34.0% 192 12.9%
_/Users/fatih/Code/set.BenchmarkIntersection100
0 0.0% 34.0% 191 12.8%
_/Users/fatih/Code/set.BenchmarkIntersection10000

Especially for "top20", there are some keywords that can be figured out, like
hash_insert (because the set package is heavliy based on maps). The
intersection method is using several other helper methods which is using
set.Copy() a lot, I'm planning to clean up it there.

However I'm especially curious about the *evacuate* or *scanblock*
keywords. What does they mean?
Is there any places I can lookup them and learn? How should I
interpret those output?

The test code can be found here:
https://github.com/fatih/set/blob/master/set_test.go#L91

Thanks in advance

Regards



--
Fatih Arslan

[peterGo]

Fatih,

evacuate: pkg/runtime/hashmap.c

scanblock: pkg/runtime/mgc0.c

Peter