POSTD PRODUCED BY NIJIBOX

POSTD PRODUCED BY NIJIBOX

ニジボックスが運営する
エンジニアに向けた
キュレーションメディア

POSTD PRODUCED BY NIJIBOX

POSTD PRODUCED BY NIJIBOX

ニジボックスが運営する
エンジニアに向けた
キュレーションメディア

FeedlyRSSTwitterFacebook

本記事は、原著者の許諾のもとに翻訳・掲載しております。

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

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の提案とフィードバックに深く感謝します。

監修者
監修者_古川陽介
古川陽介
株式会社リクルート プロダクト統括本部 プロダクト開発統括室 グループマネジャー 株式会社ニジボックス デベロップメント室 室長 Node.js 日本ユーザーグループ代表
複合機メーカー、ゲーム会社を経て、2016年に株式会社リクルートテクノロジーズ(現リクルート)入社。 現在はAPソリューショングループのマネジャーとしてアプリ基盤の改善や運用、各種開発支援ツールの開発、またテックリードとしてエンジニアチームの支援や育成までを担う。 2019年より株式会社ニジボックスを兼務し、室長としてエンジニア育成基盤の設計、技術指南も遂行。 Node.js 日本ユーザーグループの代表を務め、Node学園祭などを主宰。