http://blog.golang.org/profiling-go-programs
Robert HundtはScala Days 2011で「Loop Recognition in C++/Java/Go/Scala.」と題し論文の発表を行った。 論文ではC++, Go, Java, Scalaでのコンパイラの流動解析パスで使用するようなループ探索アルゴリズムを実装し、 これらの言語での典型的なパフォーマンスの問題についての結論を引き出すことに使用しました。 この論文で提示されたGoプログラムは非常に遅く動作します。今回この遅いプログラムを早くする事ができるか、 Goのプロファイリングツールを使用しながら実証します。
プロファイリングツールを使用して、具体的なボトルネックを特定し修正する事により Goループ探索プログラムは 6xより少ないメモリ使用量で高速に動作します。 (アップデート:最近のgcc++のlibstdcの最適化で、メモリの減少量は3.7Xになりました）
Hundtの論文は、彼が使用したC+ +、Go、Java、およびScalaのツールがどのバージョンか指定していません。 このブログ記事では Ubuntu Natty ディストリビューションで提供される最新のGo コンパイラとg++のバージョンを使用します。 (JavaとScalaは私達が効率的なプログラムを書く事に長けてなく比較は不公平なものとなるので使用しません。論文ではC++が最速の言語であったのでここでの比較は十分です） (アップデート:2013年3月に更新された投稿では、最新のamd64の開発版Goコンパイラと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と16 GBのRAMを備えたコンピュータでGentoo Linuxの3.8.4-gentoo kernel上で実行している。 このマシンは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秒で実行され、メモリは700Mを使用しています。Goプログラムは25.20秒で実行され、メモリの1,302Mを使用しています。 (これらの測定は、論文のものと調和するのは困難であるが、この記事のポイントは論文から結果を再現するのではなく、「go tool pprof」の使用方法を探ることである）
Goプログラムのチューニングを開始するためには、プロファイリングを有効にする必要があります。 コードがGo testパッケージのベンチマークのサポートを使用している場合、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()
}
...
新しいコードは、コマンドラインフラグを解析するGo flagライブラリを利用してcpuprofileフラグを定義し cpuprofileフラグがコマンドラインで設定されている場合、StartCPUProfileはファイルにリダイレクトされます。 プロファイラは、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の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」では、サンプルに現れた各関数を行に出力します。 最初の2列は、関数が実行されたサンプルの呼び出し数と全サンプル中の割合を示している。(呼び出された関数が終了するのを待っているではない) runtime.mapaccess1_fast64関数は298サンプル、11.8％で実行されていた。 トップ10の出力は、サンプル数でソートされます。 3列目はリストの累計を示しています。最初の3行は、サンプルの32.4％を占めています。 4番目と5番目の列は、(実行中または呼び出された関数が終了するのを待っているのどちらかの)関数が登場しているサンプルの数を示している。 main.FindLoops関数は、サンプルの10.6％で走っていたが、それは、サンプルの84.1％でコールスタック（関数はコールされて実行中であった）されていた。
-cumフラグ（累積的）を使用し、4番目と5番目の列でソートする：
(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分の間に再帰的なmain.DFS機能はmain.mainより100フレーム深かくなり完全なトレースは切り捨てられました。
スタック·トレース·サンプルは、関数呼び出し関係の詳細について、テキストリストを表示する事よりも興味深いデータが含まれています。webコマンドはプロファイルデータのグラフをSVG形式で書き込み、Webブラウザで開けます。（PostScript形式で書き込みGhostviewで開くことのできるgvコマンドもあります。いずれかのコマンドではgraphvizをインストールしている必要があります）
(pprof) web
完全なグラフの一部は次のようになります。
グラフの各ボックスは1つの関数に対応し、ボックスは関数が実行されていたサンプルの数に応じてサイズ調整されています。ボックスYからボックスXへのエッジは、XがYを呼び出すことを示します。エッジに沿った数がサンプルに現れる呼び出し回数です。1つの関数が複数呼び出された場合は再帰関数の呼び出のように、それぞれの外側のエッジ重みにがカウントされます。main.DFSは自己エッジで21342と示されています。
一目で、プログラムがGoのマップ値の使用に対応し、ハッシュ演算で多くの時間を費やしていることがわかります。このようなグラフからのノイズの一部をクリアしruntime.mapaccess1_fast64などの特定の関数を含むサンプルのみを使用するようにwebに指示することができます。
(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つのモードをミックスしており、行をクリックすると逆アセンブリを表示します。
私たちはハッシュランタイム関数によって、マップの検索処理に時間がかかっている事を知っているので、第2列について最も気にする。再帰的なトラバースから予想されるような時間の大部分は、DFS（ライン247）の再帰呼び出しに費やされる。再帰を除くと、ライン242、246、および250の数字マップへのアクセスに時間がかかっているように見えます。特定の検索のための場合、マップは、最も効率的な選択ではありません。コンパイラになるのと同じように、基本的なブロック構造は、割り当てられた固有のシーケンス番号を持っています。map[*BasicBlock]intを使う代わりブロック番号によってインデックスされたスライスの[]intを使うことができます。配列やスライスを使える時にマップを使用する理由はありません。
スライスにマップから数値を変更する修正をプログラム中の7行すると2倍近く実行時間を削減されます。
$ 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」コマンドはFindLoopsがおよそ82.4MB使用中の56.3MB割り当てられたことを報告している。別にcreateNodeが17.6 MBを占めている。オーバーヘッドを軽減するために、メモリプロファイラは割り当てられた半MB（「1-in-524288 sampling rate」)あたり約1ブロック分の情報が記録するため、実際のカウントの近似値である。
メモリ割り当てを見つけるために、それらの関数を一覧表示することができます。
(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.5メガバイトをマップに割り当てるされている。
余談として「--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を占めているため、マップの初期化に150byteをとるように見えます。マップがキーと値のペアを保持するために使用されている場合には合理的だが、ここにあるようにスタンドインの簡単なセットのためとして使用されていないときにはそうならない。
マップを使用する代わりに要素をリストするシンプルなスライスを使用することができます。マップが使用されている例の1つを除くすべてにおいて、アルゴリズムは重複する要素を挿入する事は不可能である。残りの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から差分を参照）
それでは再びCPUプロフィールを見てみましょう。最初始めたときより2.11x高速になった。
$ 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が呼び出されるたびにかなりの bookkeeping structuresが割り当てられる。ベンチマークはFindLoopsを50回コールするので、ガベージコレクト対象のメモリの量を増加させ、コストが高くなっている。
ガベージコレクトの機能を持つことは、メモリ割り当ての問題を無視することができるという意味ではありません。この場合のシンプルな解決策はFindLoopsの各呼び出しは以前のストレージを再利用可能なようにキャッシュを導入することです。（実際Hundtの論文で、Javaプログラムが妥当な性能を引き出すためのこの変更を行ったが、他のガベージコレクションの実装では同じ変更を行っていない。）
グローバルなキャッシュ構造を追加
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での繰り替えしや呼び出しで再利用することができ、そのパス中の別の「node pool」の生成と組み合わせることができる。同様に、ループグラフストレージは各繰り返しで再割当する代わりに再利用することができます。これらの性能の変化に加えて、最終版は、データ構造体および関数を用いて、慣用的な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.7xより速く実行され、1.5倍より少ないメモリを使用となります。
$ ./xtime ./havlak6 -reuseloopgraph=false
# of loops: 76000 (including 1 artificial root node)
3.69u 0.06s 3.76r 797120kB ./havlak6 -reuseloopgraph=false
$
もちろん、このGoプログラムとvectorが適切なところでsetのような非効率なデータ構造を使用しているような元のC++プログラムを比較する事は公正ではありません。健全性チェックとして、最終版のGoプログラムを同等のC++コードへ変換した。その実行時間は、Goのプログラムと同じようになります。
$ wc havlak6.cc; wc havlak6.go
401 1220 9040 havlak6.cc
461 1441 9467 havlak6.go
$
（havlak6.ccとhavlak6.goを参照）
ベンチマークは、測定プログラムと同じくらい良いです。非効率的なGoプログラムを学ぶために、 「go tool pprof」を使用し、1桁の性能を改善し、3.7倍のメモリ使用量を削減しました。同等に最適化されたC++プログラムとのその後の比較は、Goはプログラマが内部ループによって生成されたメモリの量について注意する事によって、C ++と競合することができることを示している。
プログラムソース、Linuxのx86-64のバイナリ、およびこの記事を書くために使用されるプロファイルは、Google Codeの上benchgraffitiプロジェクトでご利用いただけます。
前述したように、「go test」はすでにこれらのプロファイリングのフラグが含まれており、ベンチマーク関数を定義しすべてセットできる。データプロファイリングするための標準的なHTTPインタフェースもある。HTTPサーバでは、以下を追加
import _ "net/http/pprof"
「/debug/pprof/」の下にいくつかのURLハンドラを設定します。「go tool pprof」に1つの引数を指定する事で実行する事ができ、サーバのプロファイリングデータへの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ルーチンのブロッキングプロファイルは、今後の記事で説明されるので乞うご期待。
By Russ Cox, July 2011; updated by Shenghou Ma, May 2013