> Source: https://www.ymotongpoo.com/works/goblog-ja/pprof/


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

[Profiling Go Programs](https://go.dev/blog/pprof) by Russ Cox, Shenghou Ma

Scala Days 2011で、Robert Hundtが[Loop Recognition in C++/Java/Go/Scala](http://research.google.com/pubs/pub37122.html)と題した論文を発表しました。
この論文では、コンパイラのフロー解析パスで使われるようなループ検出アルゴリズムを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のベンチマークプログラム](https://github.com/hundt98847/multi-language-bench)（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パッケージ](/pkg/testing/) のベンチマーク機能を使っていれば、gotestの標準の
`-cpuprofile` と `-memprofile` フラグを使えたでしょう。
しかし今回のような単体のプログラムでは、`runtime/pprof` をインポートして、次のようなコードを数行追加する
必要があります。

```go
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ライブラリ](/pkg/flag/) を呼び出して
コマンドラインのフラグを解析し、その後 `cpuprofile` フラグがコマンドラインで指定されていれば、
そのファイルに向けて[CPUプロファイリングを開始します](/pkg/runtime/pprof/#StartCPUProfile)。
プロファイラは、プログラムが終了する前にファイルへの書き込みの保留分をフラッシュするために、
[`StopCPUProfile`](/pkg/runtime/pprof/#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プロファイラ](https://github.com/gperftools/gperftools) を
少し改変したものです。最も重要なコマンドは `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](http://www.graphviz.org/) をインストールしておく必要があります。）

```
(pprof) web
```

[グラフ全体](https://rawgit.com/rsc/benchgraffiti/master/havlak/havlak1.svg) の一部を切り出すと次のようになります。

![havlak1a-75](./havlak1a-75.png)

グラフ中の各ボックスは1つの関数に対応しており、その関数が実行中だったサンプル数に応じてボックスの大きさが
決まります。ボックスXからボックスYへ向かうエッジは、XがYを呼び出していることを示し、エッジに沿った数字は
その呼び出しがサンプルの中に現れた回数です。再帰呼び出しの場合など、1つのサンプルの中で呼び出しが複数回
現れる場合は、現れるたびにエッジの重みに加算されます。これが `main.DFS` から自分自身へ向かう自己ループの
エッジに21342という数字がついている理由です。

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

```
(pprof) web mapaccess1
```

![havlak1-hash_lookup-75](./havlak1-hash_lookup-75.png)

よく見ると、`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つのモードを組み合わせたもので、[行をクリックすると逆アセンブル結果が表示される
ソースコードのリスト](https://rawgit.com/rsc/benchgraffiti/master/havlak/havlak1.html) を表示します。

時間がハッシュのランタイム関数によって実装された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の差分](https://github.com/rsc/benchgraffiti/commit/58ac27bcac3ffb553c29d0b3fb64745c91c95948) 参照）

もう一度プロファイラを実行して、`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回実行した後にプログラムを停止させ、メモリプロファイルを
書き出して終了するようにします。

```go
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からの差分](https://github.com/rsc/benchgraffiti/commit/b78dac106bea1eb3be6bb3ca5dba57c130268232) 参照）

`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` の簡単なバリエーションを書けます。

```go
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からの差分](https://github.com/rsc/benchgraffiti/commit/245d899f7b1a33b0c8148a4cd147cb3de5228c8a) 参照）

これで開始時点から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
```

![havlak4a-mallocgc](./havlak4a-mallocgc.png)

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

```
$ go tool pprof --nodefraction=0.1 havlak4 havlak4.prof
Welcome to pprof!  For help, type 'help'.
(pprof) web mallocgc
```

![havlak4a-mallocgc-trim](./havlak4a-mallocgc-trim.png)

これで太い矢印を簡単に追えるようになり、`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` 構造体を追加します。

```go
var cache struct {
    size int
    nonBackPreds [][]int
    backPreds [][]int
    number []int
    header []int
    types []int
    last []int
    nodes []*UnionFindNode
}
```

そして `FindLoops` がメモリ確保の代わりにこれを参照するようにします。

```go
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からの差分](https://github.com/rsc/benchgraffiti/commit/2d41d6d16286b8146a3f697dd4074deac60d12a4) 参照）

プログラムをさらに整理して速くする余地はまだありますが、そのどれもがここまでで示していないような
プロファイリング手法を必要とするものではありません。内側のループで使われているワークリストは、
反復をまたいで、また `FindLoops` の呼び出しをまたいで再利用でき、そのパスの中で生成される個別の
「ノードプール」と組み合わせることもできます。同様に、ループグラフの記憶領域も、再確保するのではなく
反復ごとに再利用できます。こうした性能面の変更に加えて、[最終版](https://github.com/rsc/benchgraffiti/blob/master/havlak/havlak6.go)
はデータ構造とメソッドを使った、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++コード](https://github.com/rsc/benchgraffiti/blob/master/havlak/havlak6.cc) に翻訳してみました。
その実行時間は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](https://github.com/rsc/benchgraffiti/blob/master/havlak/havlak6.cc) と
[havlak6.go](https://github.com/rsc/benchgraffiti/blob/master/havlak/havlak6.go) を参照）

ベンチマークは、それが計測しているプログラムと同じ程度にしか信頼できません。私たちは `go tool pprof` を
使って非効率なGoプログラムを調べ、その性能を1桁改善し、メモリ使用量を3.7分の1に削減しました。
同等に最適化されたC++プログラムとのその後の比較は、内側のループでどれだけごみが生成されるかに
プログラマが注意を払えば、GoがC++と競合できることを示しています。

この記事を書くのに使ったプログラムのソース、Linux x86-64向けのバイナリ、プロファイルは
[GitHub上のbenchgraffitiプロジェクト](https://github.com/rsc/benchgraffiti/) から入手できます。

前述の通り、[`go test`](/cmd/go/#Test_packages) にはすでにこれらのプロファイリング用フラグが含まれています。
[ベンチマーク関数](/pkg/testing/) を定義すれば、それだけで準備は完了です。プロファイリングのデータに
アクセスするための標準的なHTTPインターフェースもあります。HTTPサーバーで次のようにインポートすると、

```go
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