Goプログラムのプロファイリング
Profiling Go Programs by Russ Cox, Shenghou Ma
Scala Days 2011で、Robert HundtがLoop Recognition in C++/Java/Go/Scalaと題した論文を発表しました。 この論文では、コンパイラのフロー解析パスで使われるようなループ検出アルゴリズムをC++、Go、Java、Scalaでそれぞれ実装し、 それらのプログラムを使ってこれらの言語における典型的な性能上の懸念について結論を導き出していました。 この論文で示されたGoのプログラムはかなり遅く動作しており、Goのプロファイリングツールを使って遅いプログラムを 速くする方法を示すには絶好の機会となっています。
Goのプロファイリングツールを使って特定のボトルネックを特定し修正することで、Goのループ検出プログラムを
1桁速く動作させ、メモリ使用量を6分の1に抑えられます。
（追記：gcc の libstdc++ に対する最近の最適化によって、メモリの削減幅は現在では3.7倍になっています。）
Hundtの論文では、彼が使用したC++、Go、Java、Scalaの各ツールのバージョンが明記されていません。
この記事では、6g Goコンパイラの最新のweeklyスナップショットと、Ubuntu Nattyディストリビューションに
同梱されているバージョンの g++ を使用します。
（JavaとScalaは使いません。私たちはどちらの言語でも効率的なプログラムを書くことに長けていないため、
比較が不公平になってしまうからです。論文の中でC++が最も速い言語だったので、ここでのC++との比較で十分でしょう。）
（追記：この更新版の記事では、amd64向けのGoコンパイラの最新の開発版スナップショットと、2013年3月にリリースされた
最新版の g++（4.8.0）を使用します。）
$ go version
go version devel +08d20469cc20 Tue Mar 26 08:27:18 2013 +0100 linux/amd64
$ g++ --version
g++ (GCC) 4.8.0
Copyright (C) 2013 Free Software Foundation, Inc.
...
$
これらのプログラムは、3.4GHzのCore i7-2600 CPUと16GBのRAMを搭載し、Gentoo Linuxの3.8.4-gentooカーネルを 実行しているコンピュータ上で動かします。このマシンでは次のようにしてCPUの周波数スケーリングを無効にしています。
$ sudo bash
# for i in /sys/devices/system/cpu/cpu[0-7]
do
echo performance > $i/cpufreq/scaling_governor
done
#
Hundtのベンチマークプログラム（C++版とGo版）を取得し、それぞれを1つのソースファイルにまとめ、
出力行を1行だけ残して他はすべて取り除きました。プログラムの実行時間はLinuxの time ユーティリティを使い、
ユーザー時間、システム時間、実時間、最大メモリ使用量を表示するフォーマットで計測します。
$ cat xtime
#!/bin/sh
/usr/bin/time -f '%Uu %Ss %er %MkB %C' "$@"
$
$ make havlak1cc
g++ -O3 -o havlak1cc havlak1.cc
$ ./xtime ./havlak1cc
# of loops: 76002 (total 3800100)
loop-0, nest: 0, depth: 0
17.70u 0.05s 17.80r 715472kB ./havlak1cc
$
$ make havlak1
go build havlak1.go
$ ./xtime ./havlak1
# of loops: 76000 (including 1 artificial root node)
25.05u 0.11s 25.20r 1334032kB ./havlak1
$
C++のプログラムは17.80秒で実行が完了し、700MBのメモリを使用します。
Goのプログラムは25.20秒かかり、1302MBのメモリを使用します。
（これらの計測値は論文中の値とはうまく一致しませんが、この記事の目的は論文の結果を再現することではなく、
go tool pprof の使い方を探ることです。）
Goのプログラムのチューニングを始めるには、まずプロファイリングを有効にしなければいけません。
このコードが Goのtestingパッケージ のベンチマーク機能を使っていれば、gotestの標準の
-cpuprofile と -memprofile フラグを使えたでしょう。
しかし今回のような単体のプログラムでは、runtime/pprof をインポートして、次のようなコードを数行追加する
必要があります。
var cpuprofile = flag.String("cpuprofile", "", "write cpu profile to file")
func main() {
flag.Parse()
if *cpuprofile != "" {
f, err := os.Create(*cpuprofile)
if err != nil {
log.Fatal(err)
}
pprof.StartCPUProfile(f)
defer pprof.StopCPUProfile()
}
...
この新しいコードでは cpuprofile という名前のフラグを定義し、Goのflagライブラリ を呼び出して
コマンドラインのフラグを解析し、その後 cpuprofile フラグがコマンドラインで指定されていれば、
そのファイルに向けてCPUプロファイリングを開始します。
プロファイラは、プログラムが終了する前にファイルへの書き込みの保留分をフラッシュするために、
StopCPUProfile の最後の呼び出しを必要とします。
そのため、main がreturnするときに確実にこれが実行されるよう defer を使っています。
このコードを追加したら、新しい -cpuprofile フラグを付けてプログラムを実行し、その後 go tool pprof を
実行してプロファイルを解釈できます。
$ make havlak1.prof
./havlak1 -cpuprofile=havlak1.prof
# of loops: 76000 (including 1 artificial root node)
$ go tool pprof havlak1 havlak1.prof
Welcome to pprof! For help, type 'help'.
(pprof)
go tool pprof プログラムは、GoogleのC++用pprofプロファイラ を
少し改変したものです。最も重要なコマンドは topN で、プロファイル中の上位N個のサンプルを表示します。
(pprof) top10
Total: 2525 samples
298 11.8% 11.8% 345 13.7% runtime.mapaccess1_fast64
268 10.6% 22.4% 2124 84.1% main.FindLoops
251 9.9% 32.4% 451 17.9% scanblock
178 7.0% 39.4% 351 13.9% hash_insert
131 5.2% 44.6% 158 6.3% sweepspan
119 4.7% 49.3% 350 13.9% main.DFS
96 3.8% 53.1% 98 3.9% flushptrbuf
95 3.8% 56.9% 95 3.8% runtime.aeshash64
95 3.8% 60.6% 101 4.0% runtime.settype_flush
88 3.5% 64.1% 988 39.1% runtime.mallocgc
CPUプロファイリングが有効な場合、Goのプログラムはおよそ100回/秒の頻度で停止し、その時点で実行中の
ゴルーチンのスタック上のプログラムカウンタからなるサンプルを記録します。
このプロファイルには2525個のサンプルがあるので、25秒あまりの間実行されていたことになります。
go tool pprof の出力では、サンプル中に現れた関数ごとに1行が割り当てられます。
最初の2つの列は、（呼び出した関数の戻りを待っているのではなく）その関数が実行中だったサンプルの数を、
実数とサンプル全体に対する割合の両方で示しています。
runtime.mapaccess1_fast64 関数は298個のサンプル、つまり11.8%で実行中でした。
top10 の出力はこのサンプル数でソートされています。
3番目の列はリスト中での累計を示しており、最初の3行でサンプルの32.4%を占めています。
4番目と5番目の列は、その関数が（実行中か、呼び出した関数の戻りを待っている状態かにかかわらず）
現れたサンプルの数を示しています。
main.FindLoops 関数はサンプルの10.6%で実行中でしたが、（自身か自身が呼び出した関数が実行中という意味で）
コールスタックに乗っていたのはサンプルの84.1%でした。
4番目と5番目の列でソートするには、-cum（累計、cumulativeの意味）フラグを使います。
(pprof) top5 -cum
Total: 2525 samples
0 0.0% 0.0% 2144 84.9% gosched0
0 0.0% 0.0% 2144 84.9% main.main
0 0.0% 0.0% 2144 84.9% runtime.main
0 0.0% 0.0% 2124 84.1% main.FindHavlakLoops
268 10.6% 10.6% 2124 84.1% main.FindLoops
(pprof) top5 -cum
本来なら main.FindLoops と main.main の合計は100%になるはずですが、各スタックサンプルには
下位100フレームしか含まれません。サンプルのおよそ4分の1では、再帰的な main.DFS 関数が main.main から
100フレームより深いところにあったため、完全なトレースが切り詰められてしまっています。
スタックトレースのサンプルには、テキストのリストでは示しきれない、関数の呼び出し関係についてのより興味深い
データが含まれています。web コマンドはプロファイルデータのグラフをSVG形式で書き出し、Webブラウザで
開きます。（PostScriptを書き出してGhostviewで開く gv コマンドもあります。どちらのコマンドを使うにも
graphviz をインストールしておく必要があります。）
(pprof) web
グラフ全体 の一部を切り出すと次のようになります。
グラフ中の各ボックスは1つの関数に対応しており、その関数が実行中だったサンプル数に応じてボックスの大きさが
決まります。ボックスXからボックスYへ向かうエッジは、XがYを呼び出していることを示し、エッジに沿った数字は
その呼び出しがサンプルの中に現れた回数です。再帰呼び出しの場合など、1つのサンプルの中で呼び出しが複数回
現れる場合は、現れるたびにエッジの重みに加算されます。これが main.DFS から自分自身へ向かう自己ループの
エッジに21342という数字がついている理由です。
一目見ただけで、このプログラムはハッシュ操作、つまりGoの map 値の使用に対応する処理に多くの時間を
費やしていることがわかります。web に対して、runtime.mapaccess1_fast64 のような特定の関数を含む
サンプルだけを使うように指示すれば、グラフからノイズをいくらか取り除けます。
(pprof) web mapaccess1
よく見ると、runtime.mapaccess1_fast64 の呼び出しは main.FindLoops と main.DFS から行われている
ことがわかります。
全体像についてのおおまかなイメージがつかめたので、次は特定の関数にズームインしてみましょう。
まずは短い関数である main.DFS から見てみます。
(pprof) list DFS
Total: 2525 samples
ROUTINE ====================== main.DFS in /home/rsc/g/benchgraffiti/havlak/havlak1.go
119 697 Total samples (flat / cumulative)
3 3 240: func DFS(currentNode *BasicBlock, nodes []*UnionFindNode, number map[*BasicBlock]int, last []int, current int) int {
1 1 241: nodes[current].Init(currentNode, current)
1 37 242: number[currentNode] = current
. . 243:
1 1 244: lastid := current
89 89 245: for _, target := range currentNode.OutEdges {
9 152 246: if number[target] == unvisited {
7 354 247: lastid = DFS(target, nodes, number, last, lastid+1)
. . 248: }
. . 249: }
7 59 250: last[number[currentNode]] = lastid
1 1 251: return lastid
(pprof)
このリストは DFS 関数（正確には、正規表現 DFS にマッチするすべての関数）のソースコードを示しています。
最初の3つの列は、その行を実行していたサンプル数、その行またはその行から呼び出されたコード内を実行していた
サンプル数、そしてファイル中の行番号です。関連するコマンドである disasm はソースコードのリストの代わりに
その関数の逆アセンブル結果を示し、サンプル数が十分にある場合、どの命令が高コストかを見極める助けになります。
weblist コマンドはこの2つのモードを組み合わせたもので、行をクリックすると逆アセンブル結果が表示される
ソースコードのリスト を表示します。
時間がハッシュのランタイム関数によって実装されたmapの参照に費やされていることは既にわかっているので、
2番目の列に最も注目します。時間の大部分は（247行目の）DFS への再帰呼び出しに費やされていますが、
これは再帰的な走査として予想される通りです。再帰を除くと、242行目、246行目、250行目にある number map
へのアクセスに時間が費やされているように見えます。この特定のルックアップには、mapは最も効率的な選択肢では
ありません。コンパイラの中でそうであるのと同様に、ベーシックブロックの構造体には一意な連番が割り当てられて
います。map[*BasicBlock]int を使う代わりに、ブロック番号でインデックスされた []int を使えます。
配列やスライスで済むのであれば、mapを使う理由はありません。
number をmapからスライスに変更するには、プログラム中の7行を編集するだけで済み、実行時間をほぼ半分に
削減できます。
$ make havlak2
go build havlak2.go
$ ./xtime ./havlak2
# of loops: 76000 (including 1 artificial root node)
16.55u 0.11s 16.69r 1321008kB ./havlak2
$
（havlak1とhavlak2の差分 参照）
もう一度プロファイラを実行して、main.DFS がもはや実行時間の大部分を占めなくなったことを確認できます。
$ make havlak2.prof
./havlak2 -cpuprofile=havlak2.prof
# of loops: 76000 (including 1 artificial root node)
$ go tool pprof havlak2 havlak2.prof
Welcome to pprof! For help, type 'help'.
(pprof)
(pprof) top5
Total: 1652 samples
197 11.9% 11.9% 382 23.1% scanblock
189 11.4% 23.4% 1549 93.8% main.FindLoops
130 7.9% 31.2% 152 9.2% sweepspan
104 6.3% 37.5% 896 54.2% runtime.mallocgc
98 5.9% 43.5% 100 6.1% flushptrbuf
(pprof)
main.DFS のエントリはもうプロファイルに現れず、プログラム全体の実行時間も落ちています。
今度はプログラムの時間の大半がメモリの確保とガベージコレクション（確保と定期的なガベージコレクションの
両方を行う runtime.mallocgc が時間の54.2%を占めています）に費やされています。
ガベージコレクタがなぜこれほど頻繁に実行されているのかを調べるには、何がメモリを確保しているのかを
調べなければいけません。1つの方法は、プログラムにメモリプロファイリングを追加することです。
-memprofile フラグが指定されたら、ループ検出を1回実行した後にプログラムを停止させ、メモリプロファイルを
書き出して終了するようにします。
var memprofile = flag.String("memprofile", "", "write memory profile to this file")
...
FindHavlakLoops(cfgraph, lsgraph)
if *memprofile != "" {
f, err := os.Create(*memprofile)
if err != nil {
log.Fatal(err)
}
pprof.WriteHeapProfile(f)
f.Close()
return
}
-memprofile フラグを指定してプログラムを実行し、プロファイルを書き出します。
$ make havlak3.mprof
go build havlak3.go
./havlak3 -memprofile=havlak3.mprof
$
（havlak2からの差分 参照）
go tool pprof の使い方はまったく同じです。ただし今回調べているサンプルはメモリの確保であり、
クロックのティックではありません。
$ go tool pprof havlak3 havlak3.mprof
Adjusting heap profiles for 1-in-524288 sampling rate
Welcome to pprof! For help, type 'help'.
(pprof) top5
Total: 82.4 MB
56.3 68.4% 68.4% 56.3 68.4% main.FindLoops
17.6 21.3% 89.7% 17.6 21.3% main.(*CFG).CreateNode
8.0 9.7% 99.4% 25.6 31.0% main.NewBasicBlockEdge
0.5 0.6% 100.0% 0.5 0.6% itab
0.0 0.0% 100.0% 0.5 0.6% fmt.init
(pprof)
go tool pprof は、使用中の82.4MBのうちおよそ56.3MBを FindLoops が確保していると報告しています。
CreateNode はさらに17.6MBを占めています。オーバーヘッドを減らすため、メモリプロファイラは
おおよそ0.5メガバイト確保するごとに1ブロックの情報しか記録しません（「1-in-524288 sampling rate」）。
そのため、これらは実際の値の近似値です。
メモリの確保箇所を突き止めるために、それらの関数をリストできます。
(pprof) list FindLoops
Total: 82.4 MB
ROUTINE ====================== main.FindLoops in /home/rsc/g/benchgraffiti/havlak/havlak3.go
56.3 56.3 Total MB (flat / cumulative)
...
1.9 1.9 268: nonBackPreds := make([]map[int]bool, size)
5.8 5.8 269: backPreds := make([][]int, size)
. . 270:
1.9 1.9 271: number := make([]int, size)
1.9 1.9 272: header := make([]int, size, size)
1.9 1.9 273: types := make([]int, size, size)
1.9 1.9 274: last := make([]int, size, size)
1.9 1.9 275: nodes := make([]*UnionFindNode, size, size)
. . 276:
. . 277: for i := 0; i < size; i++ {
9.5 9.5 278: nodes[i] = new(UnionFindNode)
. . 279: }
...
. . 286: for i, bb := range cfgraph.Blocks {
. . 287: number[bb.Name] = unvisited
29.5 29.5 288: nonBackPreds[i] = make(map[int]bool)
. . 289: }
...
現在のボトルネックは前回と同じで、より単純なデータ構造で足りるところでmapを使っていることのようです。
FindLoops はおよそ29.5MBのmapを確保しています。
余談ですが、go tool pprof を --inuse_objects フラグ付きで実行すると、サイズの代わりに
確保数を報告してくれます。
$ go tool pprof --inuse_objects havlak3 havlak3.mprof
Adjusting heap profiles for 1-in-524288 sampling rate
Welcome to pprof! For help, type 'help'.
(pprof) list FindLoops
Total: 1763108 objects
ROUTINE ====================== main.FindLoops in /home/rsc/g/benchgraffiti/havlak/havlak3.go
720903 720903 Total objects (flat / cumulative)
...
. . 277: for i := 0; i < size; i++ {
311296 311296 278: nodes[i] = new(UnionFindNode)
. . 279: }
. . 280:
. . 281: // Step a:
. . 282: // - initialize all nodes as unvisited.
. . 283: // - depth-first traversal and numbering.
. . 284: // - unreached BB's are marked as dead.
. . 285: //
. . 286: for i, bb := range cfgraph.Blocks {
. . 287: number[bb.Name] = unvisited
409600 409600 288: nonBackPreds[i] = make(map[int]bool)
. . 289: }
...
(pprof)
およそ20万個のmapが29.5MBを占めていることから、mapの初期確保にはおよそ150バイトかかっているように 見えます。これは、mapがキーと値のペアを保持するために使われている場合には妥当な値ですが、ここでのように mapが単純な集合の代用として使われている場合には妥当ではありません。
mapの代わりに、要素を並べるだけの単純なスライスを使えます。mapが使われている箇所のうち1つを除いて、
アルゴリズムが重複する要素を挿入することはあり得ません。残った1つのケースについては、組み込み関数
append の簡単なバリエーションを書けます。
func appendUnique(a []int, x int) []int {
for _, y := range a {
if x == y {
return a
}
}
return append(a, x)
}
この関数を書くのに加えて、Goのプログラムをmapの代わりにスライスを使うように変更するには、 ほんの数行のコードを変えるだけで済みます。
$ make havlak4
go build havlak4.go
$ ./xtime ./havlak4
# of loops: 76000 (including 1 artificial root node)
11.84u 0.08s 11.94r 810416kB ./havlak4
$
（havlak3からの差分 参照）
これで開始時点から2.11倍速くなりました。もう一度CPUプロファイルを見てみましょう。
$ make havlak4.prof
./havlak4 -cpuprofile=havlak4.prof
# of loops: 76000 (including 1 artificial root node)
$ go tool pprof havlak4 havlak4.prof
Welcome to pprof! For help, type 'help'.
(pprof) top10
Total: 1173 samples
205 17.5% 17.5% 1083 92.3% main.FindLoops
138 11.8% 29.2% 215 18.3% scanblock
88 7.5% 36.7% 96 8.2% sweepspan
76 6.5% 43.2% 597 50.9% runtime.mallocgc
75 6.4% 49.6% 78 6.6% runtime.settype_flush
74 6.3% 55.9% 75 6.4% flushptrbuf
64 5.5% 61.4% 64 5.5% runtime.memmove
63 5.4% 66.8% 524 44.7% runtime.growslice
51 4.3% 71.1% 51 4.3% main.DFS
50 4.3% 75.4% 146 12.4% runtime.MCache_Alloc
(pprof)
今度はメモリの確保とそれに伴うガベージコレクション（runtime.mallocgc）が実行時間の50.9%を占めています。
システムがなぜガベージコレクションを行っているのかを調べる別の方法は、コレクションを引き起こしている
確保、つまり mallocgc の中で最も時間を費やしている確保を見ることです。
(pprof) web mallocgc
サンプル数の少ない多くのノードが大きなノードを覆い隠してしまっているので、このグラフからは何が起きて
いるのか判別するのが困難です。go tool pprof に対して、サンプルの少なくとも10%を占めていないノードを
無視するように指示できます。
$ go tool pprof --nodefraction=0.1 havlak4 havlak4.prof
Welcome to pprof! For help, type 'help'.
(pprof) web mallocgc
これで太い矢印を簡単に追えるようになり、FindLoops がガベージコレクションの大部分を引き起こしていることが
わかります。FindLoops をリストすると、その多くが関数の冒頭に集中していることがわかります。
(pprof) list FindLoops
...
. . 270: func FindLoops(cfgraph *CFG, lsgraph *LSG) {
. . 271: if cfgraph.Start == nil {
. . 272: return
. . 273: }
. . 274:
. . 275: size := cfgraph.NumNodes()
. . 276:
. 145 277: nonBackPreds := make([][]int, size)
. 9 278: backPreds := make([][]int, size)
. . 279:
. 1 280: number := make([]int, size)
. 17 281: header := make([]int, size, size)
. . 282: types := make([]int, size, size)
. . 283: last := make([]int, size, size)
. . 284: nodes := make([]*UnionFindNode, size, size)
. . 285:
. . 286: for i := 0; i < size; i++ {
2 79 287: nodes[i] = new(UnionFindNode)
. . 288: }
...
(pprof)
FindLoops が呼ばれるたびに、それなりに大きな管理用の構造体を確保しています。このベンチマークは
FindLoops を50回呼び出すので、これらが積み重なってかなりの量のごみとなり、ガベージコレクタにとって
かなりの量の仕事になっています。
ガベージコレクション付きの言語だからといって、メモリの確保に関する問題を無視してよいわけではありません。
今回のケースでは、簡単な解決策として、FindLoops の呼び出しごとに可能な限り前回の呼び出しの領域を
再利用できるようにキャッシュを導入することが挙げられます。（実際、Hundtの論文では、Javaのプログラムには
まさにこの変更が必要でそれなりの性能を得られたと説明されていますが、他のガベージコレクション付きの
実装には同じ変更を加えていません。）
グローバルな cache 構造体を追加します。
var cache struct {
size int
nonBackPreds [][]int
backPreds [][]int
number []int
header []int
types []int
last []int
nodes []*UnionFindNode
}
そして FindLoops がメモリ確保の代わりにこれを参照するようにします。
if cache.size < size {
cache.size = size
cache.nonBackPreds = make([][]int, size)
cache.backPreds = make([][]int, size)
cache.number = make([]int, size)
cache.header = make([]int, size)
cache.types = make([]int, size)
cache.last = make([]int, size)
cache.nodes = make([]*UnionFindNode, size)
for i := range cache.nodes {
cache.nodes[i] = new(UnionFindNode)
}
}
nonBackPreds := cache.nonBackPreds[:size]
for i := range nonBackPreds {
nonBackPreds[i] = nonBackPreds[i][:0]
}
backPreds := cache.backPreds[:size]
for i := range nonBackPreds {
backPreds[i] = backPreds[i][:0]
}
number := cache.number[:size]
header := cache.header[:size]
types := cache.types[:size]
last := cache.last[:size]
nodes := cache.nodes[:size]
もちろん、このようなグローバル変数はソフトウェア工学的には良くない習慣です。FindLoops を並行に
呼び出すことが安全ではなくなってしまうからです。今のところ、私たちのプログラムの性能にとって何が
重要なのかを理解するために、可能な限り最小限の変更にとどめています。この変更は単純で、Java実装の
コードを反映したものです。Goプログラムの最終版では、このメモリを追跡するために専用の LoopFinder
インスタンスを使い、並行利用の可能性を取り戻すことになります。
$ make havlak5
go build havlak5.go
$ ./xtime ./havlak5
# of loops: 76000 (including 1 artificial root node)
8.03u 0.06s 8.11r 770352kB ./havlak5
$
（havlak4からの差分 参照）
プログラムをさらに整理して速くする余地はまだありますが、そのどれもがここまでで示していないような
プロファイリング手法を必要とするものではありません。内側のループで使われているワークリストは、
反復をまたいで、また FindLoops の呼び出しをまたいで再利用でき、そのパスの中で生成される個別の
「ノードプール」と組み合わせることもできます。同様に、ループグラフの記憶領域も、再確保するのではなく
反復ごとに再利用できます。こうした性能面の変更に加えて、最終版
はデータ構造とメソッドを使った、Goらしいスタイルで書かれています。こうしたスタイル面の変更が実行時間に
与える影響はわずかで、アルゴリズムと制約は変わっていません。
最終版は2.29秒で実行が完了し、351MBのメモリを使用します。
$ make havlak6
go build havlak6.go
$ ./xtime ./havlak6
# of loops: 76000 (including 1 artificial root node)
2.26u 0.02s 2.29r 360224kB ./havlak6
$
これは私たちが出発した時点のプログラムから11倍速くなっています。生成されたループグラフの再利用を 無効にして、キャッシュされるメモリがループ検出の管理用データだけになる場合でも、このプログラムは 元のプログラムより6.7倍速く動作し、メモリ使用量は1.5分の1になります。
$ ./xtime ./havlak6 -reuseloopgraph=false
# of loops: 76000 (including 1 artificial root node)
3.69u 0.06s 3.76r 797120kB ./havlak6 -reuseloopgraph=false
$
もちろん、vector の方が適切な場面で set のような非効率なデータ構造を使っていた元のC++プログラムと
このGoプログラムを比較するのは、もはや公平ではありません。健全性を確認するため、最終版のGoプログラムを
同等のC++コード に翻訳してみました。
その実行時間はGoプログラムのものとよく似ています。
$ make havlak6cc
g++ -O3 -o havlak6cc havlak6.cc
$ ./xtime ./havlak6cc
# of loops: 76000 (including 1 artificial root node)
1.99u 0.19s 2.19r 387936kB ./havlak6cc
Goのプログラムは、C++のプログラムとほぼ同じ速さで動作しています。C++のプログラムは明示的なキャッシュの 代わりに自動的な削除と確保を使っているため、C++のプログラムのほうがやや短く書きやすくはなっていますが、 その差は劇的というほどではありません。
$ wc havlak6.cc; wc havlak6.go
401 1220 9040 havlak6.cc
461 1441 9467 havlak6.go
$
（havlak6.cc と havlak6.go を参照）
ベンチマークは、それが計測しているプログラムと同じ程度にしか信頼できません。私たちは go tool pprof を
使って非効率なGoプログラムを調べ、その性能を1桁改善し、メモリ使用量を3.7分の1に削減しました。
同等に最適化されたC++プログラムとのその後の比較は、内側のループでどれだけごみが生成されるかに
プログラマが注意を払えば、GoがC++と競合できることを示しています。
この記事を書くのに使ったプログラムのソース、Linux x86-64向けのバイナリ、プロファイルは GitHub上のbenchgraffitiプロジェクト から入手できます。
前述の通り、go test にはすでにこれらのプロファイリング用フラグが含まれています。
ベンチマーク関数 を定義すれば、それだけで準備は完了です。プロファイリングのデータに
アクセスするための標準的なHTTPインターフェースもあります。HTTPサーバーで次のようにインポートすると、
import _ "net/http/pprof"
/debug/pprof/ 以下のいくつかのURLに対応するハンドラがインストールされます。
その後、サーバーのプロファイリングデータのURLを1つの引数として指定して go tool pprof を実行すれば、
稼働中のプロファイルをダウンロードして調べられます。
go tool pprof http://localhost:6060/debug/pprof/profile # 30秒間のCPUプロファイル
go tool pprof http://localhost:6060/debug/pprof/heap # ヒーププロファイル
go tool pprof http://localhost:6060/debug/pprof/block # ゴルーチンのブロッキングプロファイル
ゴルーチンのブロッキングプロファイルについては、今後の記事で説明する予定です。お楽しみに。
By Russ Cox, Shenghou Ma