Go言語でプロファイリング（CPU profiling検証編）
Go言語ではプロファイリングを行えるようになっています。
- CPU profiling
- MEMORY recycling
まずは「Go Profiling - John Graham-Cumming」のスライドを元にCPU profilingを試してみました。
※試してみただけでどう対応すべきかについては述べません
CPU profiling
CPUプロファイリングはコード内のどの箇所に時間がかかっているかを調べるのに使用できます。
検証コードはこちらの内容から利用させていただいてます。
type Item struct { key string value string last time.Time } type Cache struct { cap int data map[string]*Item } func NewCache(cap int) *Cache { return &Cache{cap, make(map[string]*Item)} } func (c *Cache) makeSpace() { old := &Item{last: time.Now()} var key string for k, v := range c.data { if v.last.Before(old.last) { old = v key = k } } delete(c.data, key) } func (c *Cache) Put(key, value string) { if len(c.data) == c.cap { c.makeSpace() } c.data[key] = &Item{key, value, time.Now()} } func (c *Cache) Get(key string) *Item { if c.data[key] != nil { c.data[key].last = time.Now() } return c.data[key] }
これはキャッシュの実装です。キャッシュする最大件数を指定しておき、最大数を超えた場合はもっともアクセスのなかった古いものから削除されていくというものです。
この実装に対してキャッシュサイズ10000、対象データ数1000000件、キーの最大数15000（古いキャッシュを削除するために10000以上に設定）で実行します。
一度実行しみます。
$ go build -o lrutest1.exe lrutest1.go $ lrutest1.exe < top10M.csv 1000000 total 337773 misses 1m53.7145041s passed.
1000000件中337773がキャッシュにヒットせず、1分53秒程度かかっているということです。
これをCPUプロファイリングしていきたいと思います。
まずはmain関数の最初に
// lrutest1.cpuprofileは結果の出力先、ファイル名は任意 f, _ := os.Create("lrutest1.cpuprofile") pprof.StartCPUProfile(f) defer pprof.StopCPUProfile()
を追記します。先程と同じように実行すると今度はlrutest1.cpuprofileというファイルが出力されるので、以下のコマンドを実行します。
$ go tool pprof lrutest1.exe lrutest1.cpuprofile lrutest1.cpuprofile: need a 64-bit perl to process this 64-bit profile.
はい、きました。いつものWindowsいじめです。現在の環境にはmsysgit（これ32bit）が入っていてそのなかのperl.exeを参照しているようです。
解決策はEx Nihilo: Profiling Go with pprof under Windowsに書いてあるとおりで、
と。ちなみにUbuntuでは上記コマンド1発でOKです。
で環境を整えて再挑戦。
perl %GOROOT%\pkg\tool\windows_amd64\pprof lrutest1.exe lrutest1.cpuprofile Welcome to pprof! For help, type 'help'. (pprof)
はい、やっとでました。(pprof)というプロンプトで止まっているので、コマンドを入力します。
(pprof) top
Total: 11044 samples
4343 39.3% 39.3% 10902 98.7% github.com/taknb2nch/go-profiling/lru1.(*Cache).makeSpace
3128 28.3% 67.6% 3128 28.3% hash_next
2216 20.1% 87.7% 2982 27.0% runtime.mapiter2
572 5.2% 92.9% 572 5.2% runtime.memcopy64
441 4.0% 96.9% 3572 32.3% runtime.mapiternext
195 1.8% 98.7% 195 1.8% runtime.strcopy
23 0.2% 98.9% 24 0.2% bufio.(*Reader).ReadRune
22 0.2% 99.1% 30 0.3% runtime.mallocgc
11 0.1% 99.2% 66 0.6% encoding/csv.(*Reader).parseField
10 0.1% 99.2% 29 0.3% bytes.(*Buffer).WriteRunetopコマンドはプロファイル数、-cumオプションをつけると、累積数が出るようです。（それが何なのかというツッコミはなしで）
(pprof) top -cum
Total: 11044 samples
0 0.0% 0.0% 11039 100.0% runtime.gosched0
0 0.0% 0.0% 11039 100.0% runtime.main
1 0.0% 0.0% 11039 100.0% text
1 0.0% 0.0% 10915 98.8% github.com/taknb2nch/go-profiling/lru1.(*Cache).Put
4343 39.3% 39.3% 10902 98.7% github.com/taknb2nch/go-profiling/lru1.(*Cache).makeSpace
441 4.0% 43.3% 3572 32.3% runtime.mapiternext
3128 28.3% 71.7% 3128 28.3% hash_next
2216 20.1% 91.7% 2982 27.0% runtime.mapiter2
572 5.2% 96.9% 572 5.2% runtime.memcopy64
195 1.8% 98.7% 195 1.8% runtime.strcopyCache.makeSpaceメソッドにコストがかかっているのがわかります。
またこの結果を視覚化することもできます。視覚化するためにはGraphvizをインストールしなくてはなりません。リンク先からダウンロードして、パスを通しておいてください。（Ubuntuならapt-get instal graphvizでいけます）
インストール後以下のコマンドを実行します。
$ perl %GOROOT%\pkg\tool\windows_amd64\pprof --web lrutest1.exe lrutest1.cpuprofile Dropping nodes with <= 55 samples; edges with <= 11 abs(samples) 'dot' は、内部コマンドまたは外部コマンド、 操作可能なプログラムまたはバッチ ファイルとして認識されていません。 ...
（Ubuntuでは $ go tool pprof --web lrutest1.exe lrutest1.cpuprofile）
はい、またきました、動きません。
本らならデフォルトのブラウザが起動して、出力結果のが表示されるのですが、perlのスクリプトがWindowsに対応していないようです。（Ubuntuでは問題なく動きます）
しかしsvgのファイル自体はtempに出力されるのでブラウザで開けばOKです。
このようにグラフで表示されます。やはり視覚化すると非常に分かりやすいです。結果が一目瞭然なので、その部分を修正していくことになります。
pprof には他にもたくさんオプションがあるようなのですが、今回はここまでに止めておきたいと思います。
