go testでベンチマークを取ってpprofで時間がかかっている箇所を調べる

(2017-01-04)

この関数のベンチマークを取る。

package cal

import (
	"math/big"
)

var cache = map[int]*big.Int{}

func resetCache() {
	cache = map[int]*big.Int{}
}

func Fibonacci(n int) *big.Int {

	if c := cache[n]; c != nil {
		return c
	}

	ret := new(big.Int)
	before := big.NewInt(1)
	for i := 1; i < n; i++ {
		tmp := new(big.Int).Add(ret, before)
		before = ret
		ret = tmp
		cache[i] = ret
	}
	cache[n] = ret
	return ret
}

引数にtesting.Bを取る、Benchmarkから始まる関数を書いて、b.N回ループさせる。

package cal

import (
	"math/big"
	"testing"
)

func TestFibonacci(t *testing.T) {
	if f := Fibonacci(10); f.String() != big.NewInt(34).String() {
		t.Errorf("%d != %d (expected)", f, big.NewInt(34))
	}
}

func BenchmarkFibonacci(b *testing.B) {
	for i := 0; i < b.N; i++ {
		b.StopTimer()
		resetCache()
		b.StartTimer()
		Fibonacci(100)
	}
}

これをgo test -benchで実行するとベンチマークが取れる。さらに-benchmemを付けるとメモリアロケーションの情報も出る。 また、-cpuprofileでCPUのプロファイルを出力し、pprocに渡すことでどの部分で時間がかかっているかを調べることができる。

https://golang.org/cmd/go/#hdr-Description_of_testing_flags

$ go test -bench Fibonacci -benchmem -o pprof/test.bin  -cpuprofile pprof/cpu.out ./cal
BenchmarkFibonacci-4   	   50000	     32788 ns/op	   13344 B/op	     211 allocs/op
PASS
ok  	github.com/sambaiz/try-pprof/cal	3.406s

$ go tool pprof --text pprof/test.bin pprof/cpu.out
3.80s of 3.83s total (99.22%)
Dropped 17 nodes (cum <= 0.02s)
      flat  flat%   sum%        cum   cum%
     2.31s 60.31% 60.31%      2.31s 60.31%  runtime.mach_semaphore_signal
     0.38s  9.92% 70.23%      0.38s  9.92%  runtime.mach_semaphore_timedwait
     0.32s  8.36% 78.59%      0.32s  8.36%  runtime.mach_semaphore_wait
     0.27s  7.05% 85.64%      0.27s  7.05%  runtime.usleep
     0.14s  3.66% 89.30%      0.14s  3.66%  runtime.deductSweepCredit
     0.09s  2.35% 91.64%      0.28s  7.31%  runtime.mallocgc
     0.04s  1.04% 92.69%      0.14s  3.66%  runtime.mapassign1
     0.04s  1.04% 93.73%      0.05s  1.31%  runtime.updatememstats
     0.03s  0.78% 94.52%      0.13s  3.39%  math/big.nat.add
     0.03s  0.78% 95.30%      0.03s  0.78%  runtime.aeshash64
...

graphvizをインストールすることでsvgのグラフを出すこともできる。

$ brew install graphviz
$ go tool pprof --svg pprof/test.bin pprof/cpu.out > pprof/test.svg

svgで出力したもの