go tool traceでgoroutineの実行状況を可視化する

こんにちわ。しいたけです。今日はgoroutineの実行状況をいいかんじに可視化するツールの話です。

goのプロファイリングツールと言えば、 runtime/pprof や net/http/pprof ですよね。これらの使い方はググればすぐに出てくるのですが、 詳細なtraceを取得して可視化できる runtime/trace については、日本語の情報が殆ど無いので書いてみましいたけ。

runtime/trace はgoroutineの実行状況やsystem callのイベント、Heapやnetworkの状況をこんな感じに可視化してくれるので便利です。

これは自作のクローラーを動かしている際のtraceを可視化したもので、横軸がタイムラインになっており、上段に Heapの使用状況やgoroutineとos threadの数が, 下段はnetworkやProccesor(GOMAXPROCSで指定するgoroutineの実行環境)毎にどのコードが実行されているか、が表示されます。

Heapやgoroutines数の増減と処理の関連を時系列で追えるので、大まかなボトルネックの特定に便利です。また、各goroutine毎の開始/終了とsystem callやunblockイベント(goroutineの切り替え)を細かく追えるので、goroutineが刺さっている箇所の特定にも役立ちます

右側のboxの↓アイコンをクリックした上で、グラフ上でドラッグするとzoomin/outできます。また、View Options で Flow Eventsをチェックすると矢印が描画されます

ここに、実際に動かせるサンプルを置いておきます。

• http://yuroyoro.net/gotrace01/trace.html
• http://yuroyoro.net/gotrace02/trace.html

これはとある自作Proxyのtraceの一部で、Proc3で実行されている皆さんおなじみの net/http.(*conn).serve がリクエストを受けて、 go 構文で新たなgoroutineを起動してProc2で実行される様子です。このように、どのタイミングでどのgoroutineが動いたのかが一目瞭然です。

これはGCが実行されている様子です。ほとんどのProcでGC関連の処理が動いた後に、上段のHeapのallocatedが減っている様子が見てとれます。

で、このtraceの可視化の方法ですが、 手っ取り早いのは runtime/trace パッケージをimportして、 trace.Start(w io.Writer) と trace.Stop() を呼び出す方法です

https://golang.org/pkg/runtime/trace/

package main

import (
    "log"
    "os"
    "runtime"
    "runtime/trace"
)

func main() {

    f, err := os.Create("trace.out")
    if err != nil {
        log.Fatal(err)
    }
    defer f.Close()

    trace.Start(f)
    defer trace.Stop()

  // do something ...
}

このように、traceを取得したい処理の前後で trace.Start を呼び出すと、結果がファイルに出力されます。 そのファイルを go tool trace コマンドの引数に渡すと、ブラウザで取得したtraceを分析できるようになります。

net/http/pprof パッケージを使っているウェブアプリケーションでも、簡単にtraceを取得することができます。

pprofがlistenしているなら、 /debug/pprof/trace?seconds=5 にリクエストを送ると、5秒間のtraceを取得して結果をダウンロードできます。得られたファイルを go tool trace に渡せば、同様にブラウザ上で分析できます。

詳細なボトルネックの分析は、 pprofやgo-torchでのflamegraphの分析が有向ですが、 go tool trace では時系列に対応しての分析が可能なので、それぞれ状況に合わせて使い分けると良いのではないかと思いましいたけ。

F.Y.I.

• Go Execution Tracer
• go tool trace - Making Pusher