本投稿では、私が取り組んでいる試験的なツールを紹介します。

gcvisはGoプロセスのガーベジコレクタのオペレーションを視覚化するシンプルな手法です。以下は、作動中のgcvisのスクリーンショットです。

ここからは、gcvisの仕組みとgcvisから得られる結果をどう解釈するかについて検証します。

gcvisでデータを取得する方法

Goプログラムからデータを取得するには、いくつかの方法があります。

ビルトインプロファイラは、 net/http/pprof 、または、私の プロファイル パッケージから利用できますが、プログラムのソースを改変できない場合があります。

他には、それぞれのGoプログラムに組み込まれている遠隔測定データのソースもあり、以下の環境変数を指定することでアクセスできます。

GODEBUG=gctrace=1

（環境変数GODEBUGは、 ランタイム パッケージで提供されています）

この環境変数を指定してプログラムを起動すると、標準出力に以下の追加出力が出力されます（少し簡略化されています）。

% env GODEBUG=gctrace=1 godoc -http=:6060
...
gc76(1): 2+1+1390+1 us, 1 -> 3 MB, 16397 (1015746-999349) objects, 1436/1/0 sweeps, 0(0) handoff, 0(0) steal, 0/0/0 yields
gc77(1): 2+0+1582+1 us, 2 -> 4 MB, 14623 (1016248-1001625) objects, 1436/0/0 sweeps, 0(0) handoff, 0(0) steal, 0/0/0 yields
scvg0: inuse: 6, idle: 15, sys: 22, released: 0, consumed: 22 (MB)
scvg1: inuse: 6, idle: 15, sys: 22, released: 0, consumed: 22 (MB)
gc78(1): 5+1+4814+1 us, 2 -> 2 MB, 21076 (1023168-1002092) objects, 1436/25/0 sweeps, 0(0) handoff, 0(0) steal, 0/0/0 yields
scvg2: GC forced
scvg2: inuse: 6, idle: 15, sys: 22, released: 0, consumed: 22 (MB)

ここで提示されている2種類の情報は

• それぞれのガーベジコレクションのサイクルを表す行。プレフィックスgcで示されます。
• スカベンジャのオペレーションを表す一連の行。プレフィックスscvgで示され、使用されていないヒープ領域をオペレーティングシステムに返す役割を担います。

次のセクションでは、gcvisの使い方とgcvisから得られるデータの解釈の仕方について述べます。

gcvisを使用する

gcvisを使用するには、timeやniceと同じように、検証をしたいGoプログラムの前に置きます。

以下はインデクシングモードでgodocと一緒にgcvisを使用した例です（メモリとCPU時間を大量に消費し、興味深いデータを生成しています）。

% gcvis godoc -index -http=:6060
2014/07/11 16:29:12 opening browser window, if this fails, navigate to http://127.0.0.1:53267/
Created new window in existing browser session.

以上です。

gcvisはGODEBUGの適切な値を設定し、生成された追加情報を取り除く処理をします。gcvisはまた可視化したデータを見るためにブラウザのウィンドウを開こうとします。この機能は pkg/browser によってもたらされ、オペレーティングシステムに、いくらか依存しているところがあります。

gcvisはリアルタイムでgcデバッグ行を記録しているので、タイムスタンプ情報を追加することが可能です。これは最初に記録されたままのデータであるGODEBUG出力に現在欠けている機能です。

この例では、ヒープが増えるにつれ、gcサイクルの頻度が減少しているのが分かります。

gcデバッグデータの主な用途は、ヒープ上でライブオブジェクトのサイズを記録することにあります。しかしながら、これだとヒープの全体のサイズや、ライブオブジェクトがヒープ内に占める割合が分かりません。そのため、スカベンジャからデバッグ情報を追加する必要があります。

スカベンジャは現在では2分ごとにタイマーで実行されるのでプログラム開始の数分後にしかgcvisへデータの報告が開始されません。以下は約15分間稼働した後の例です。

このグラフにおいて注意すべき興味深い点は以下のとおりです。

• scvg.sysはオペレーティングシステムからリクエストされたメモリの総量を表し、これはtopのようなツールによって報告されたVSS値に近似しています。
• scvg.inuseはヒープ全体で使用中のメモリ量で、使われなくなったオブジェクトが含まれていることがあります。scvg.inuseとgc.heapinuseは異なる時間に報告されるので、互いを正確に追跡していない可能性があります。
• scvg.idleは、ガーベジコレクタによって現在は不使用と判断されたメモリを表します。つまり、以前は使われなくなったオブジェクトを含んでいましたが、ガーベジコレクション後の今は不使用のメモリです。
• スカベンジャが実行されると、scvg.idleはscvg.inuseの減少に伴って増加します。
• メモリが不使用の状態がある程度続くと、スカベンジャがそのメモリはもう必要ないとオペレーティングシステムに通知します。これはscvg.releasedによって報告され、scvg.consumedの低下とマッチします。オペレーティングシステムはそのリクエストを自由に無視することができ、そしてそれは頻繁に起こります。

結論

コードは Github上のオープンソース なので、取得して自分のアプリケーションで試してみてください。

go get -u -v github.com/davecheney/gcvis

gcvisが役に立つかどうか、他のGoユーザからのご意見を心からお待ちしています。プルリクエストやバグレポートも大歓迎です。

Damian Gryski、Matthew Holt、Bill Kennedyの提案とフィードバックに深く感謝します。