Goブログ

Goプログラムのプロファイリング

Russ Cox、2011年7月;Shenghou Maによる更新、2013年5月
2011年6月24日

Scala Days 2011において、Robert Hundtは「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コンパイラと、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行だけ残しました。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テストパッケージのベンチマークサポートを使用した場合、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フラグリブラリを呼び出してコマンドラインフラグを解析します。そして、コマンドラインでcpuprofileフラグが設定されている場合、そのファイルにリダイレクトされたCPUプロファイリングを開始します。プロファイラーは、プログラムが終了する前にファイルへの保留中の書き込みをフラッシュするために、StopCPUProfileへの最終呼び出しが必要です。deferを使用して、mainが返るときにこれが確実に実行されるようにします。

このコードを追加した後、新しい-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のpprof C++プロファイラーのわずかに異なるバージョンです。最も重要なコマンドは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プログラムは約1秒間に100回停止し、現在実行中のゴルーチンのスタック上のプログラムカウンタで構成されるサンプルを記録します。プロファイルには2525個のサンプルがあるため、25秒強実行されていました。go tool pprofの出力には、サンプルに表示された各関数に対応する行があります。最初の2つの列は、関数の実行中(呼び出された関数の返却を待っている状態ではない)のサンプル数を、生のカウントと総サンプル数の割合で示しています。runtime.mapaccess1_fast64関数は298個のサンプル、つまり11.8%実行されていました。top10出力は、このサンプル数でソートされます。3列目は、リスト中の実行合計を示しています。最初の3行はサンプルの32.4%を占めています。4列目と5列目は、関数が出現したサンプル数(実行中または呼び出された関数の返却を待っている状態)を示しています。main.FindLoops関数はサンプルの10.6%実行されていましたが、サンプルの84.1%で呼び出しスタックに存在していました(関数自体または関数が呼び出した関数が実行されていました)。

4列目と5列目でソートするには、-cum(累積)フラグを使用します。

(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.FindLoopsmain.mainの合計は100%のはずですが、各スタックサンプルには下位100個のスタックフレームしか含まれていません。サンプルの約4分の1で、再帰的なmain.DFS関数はmain.mainよりも100フレーム以上深い位置にあったため、完全なトレースが切り捨てられました。

スタックトレースサンプルには、テキストリストでは表示できない関数呼び出し関係に関するより興味深いデータが含まれています。webコマンドは、プロファイルデータのグラフをSVG形式で書き込み、Webブラウザで開きます。(PostScriptを書き込み、Ghostviewで開くgvコマンドもあります。どちらのコマンドにも、graphvizのインストールが必要です。)

(pprof) web

完全なグラフの小さな断片は次のようになります。

グラフの各ボックスは単一の関数に対応し、ボックスのサイズは、関数が実行されていたサンプルの数に応じて変化します。ボックスXからボックスYへのエッジは、XがYを呼び出すことを示しています。エッジに沿った数は、サンプルにその呼び出しが出現した回数です。再帰的な関数呼び出しなど、単一のサンプルに呼び出しが複数回出現する場合は、各出現回数がエッジの重みにカウントされます。これは、main.DFS自身への自己エッジの21342を説明しています。

一見しただけで、プログラムがハッシュ操作に多くの時間を費やしていることがわかります。これは、Goのmap値の使用に対応しています。runtime.mapaccess1_fast64など、特定の関数を含むサンプルのみを使用するようにwebに指示すると、グラフからノイズの一部を削除できます。

(pprof) web mapaccess1

目を凝らして見ると、runtime.mapaccess1_fast64への呼び出しがmain.FindLoopsmain.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つのモードを組み合わせます。これは行をクリックすると逆アセンブリが表示されるソースリストを示しています。

ハッシュランタイム関数によって実装されたマップのルックアップに時間がかかっていることはすでにわかっているので、2列目が最も重要です。時間の大きな割合は、再帰的なDFSへの呼び出し(247行目)に費やされており、これは再帰的なトラバーサルで予想されることです。再帰を除くと、時間は242行目、246行目、250行目のnumberマップへのアクセスに費やされているように見えます。その特定のルックアップでは、マップは最も効率的な選択肢ではありません。コンパイラの場合と同様に、基本ブロック構造には一意のシーケンス番号が割り当てられています。map[*BasicBlock]intを使用する代わりに、ブロック番号でインデックスされたスライスである[]intを使用できます。配列またはスライスで十分な場合、マップを使用する理由はありません。

numberをマップからスライスに変更するには、プログラムの7行を編集するだけで、実行時間をほぼ2分の1に短縮できます。

$ make havlak2
go build havlak2.go
$ ./xtime ./havlak2
# of loops: 76000 (including 1 artificial root node)
16.55u 0.11s 16.69r 1321008kB ./havlak2
$

(havlak1havlak2の違いを参照してください)

プロファイラーを再度実行して、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コマンドによると、FindLoopsは約82.4MBのうち約56.3MBを割り当てており、CreateNodeはさらに17.6MBを割り当てています。オーバーヘッドを削減するために、メモリプロファイラは、割り当てられた524,288ブロックにつき約1ブロックの情報のみを記録します(「1/524288のサンプリングレート」)。そのため、これらは実際の値の近似値です。

メモリ割り当てを見つけるには、これらの関数をリストすることができます。

(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:     }
...

現在のボトルネックは以前と同じようです。より単純なデータ構造で十分な場合に、マップを使用していることが問題です。FindLoopsは約29.5MBのマップを割り当てています。

補足として、--inuse_objectsフラグを付けてgo tool pprofを実行すると、サイズではなく割り当てカウントが報告されます。

$ 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万個のマップが29.5MBを占めていることから、マップの初期割り当ては約150バイトのようです。キーと値のペアを保持するためにマップを使用する場合には妥当な値ですが、単純な集合の代わりにマップを使用しているこのケースでは、妥当ではありません。

マップの代わりに、要素をリストする単純なスライスを使用できます。マップが使用されているケースのほとんどでは、アルゴリズムが重複する要素を挿入することは不可能です。残りの1つのケースでは、組み込み関数appendの単純なバリアントを作成できます。

func appendUnique(a []int, x int) []int {
    for _, y := range a {
        if x == y {
            return a
        }
    }
    return append(a, x)
}

その関数を作成することに加えて、Goプログラムでマップの代わりにスライスを使用するには、数行のコードを変更するだけです。

$ 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

サンプル数が少ないノードが大きなノードを隠しているため、このグラフで何が起きているのかを判断するのは困難です。サンプルの少なくとも10%を占めていないノードを無視するようにgo tool pprofに指示できます。

$ 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倍減少します。

$ ./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プログラムを調査するためにgo tool pprofを使用し、その後、パフォーマンスを桁違いに向上させ、メモリ使用量を3.7倍削減しました。同等に最適化されたC++プログラムとの後続の比較により、プログラマが内部ループによって生成されるガベージの量に注意すれば、GoはC++と競争力を持つことができることが示されています。

この投稿の作成に使用されたプログラムソース、Linux x86-64バイナリ、およびプロファイルは、GitHubのbenchgraffitiプロジェクトで入手できます。

前述のように、go testにはこれらのプロファイリングフラグが既に含まれています。ベンチマーク関数を定義するだけで設定完了です。プロファイリングデータへの標準的なHTTPインターフェースもあります。HTTPサーバーでは、

import _ "net/http/pprof"

を追加すると、/debug/pprof/の下にあるいくつかのURLのハンドラがインストールされます。その後、引数を1つだけ指定してgo tool pprofを実行できます。これは、サーバーのプロファイリングデータへのURLであり、ライブプロファイルをダウンロードして調べます。

go tool pprof http://localhost:6060/debug/pprof/profile   # 30-second CPU profile
go tool pprof http://localhost:6060/debug/pprof/heap      # heap profile
go tool pprof http://localhost:6060/debug/pprof/block     # goroutine blocking profile

ゴルーチンのブロッキングプロファイルについては、今後の投稿で説明します。ご期待ください。

次の記事:Goのファーストクラス関数
前の記事:外部Goライブラリのスポットライト
ブログ索引