golang でのデバッグに非常に便利な go tool trace

なぜかおかしな振る舞いをするサーバプログラムをデバッグするというのは、それなりに骨の折れる作業です。大量のソースを前に「ここが怪しい」と言いながらデバッグログを埋め込むこともあるでしょう。また、lsof や ss といったコマンドやスタックトレースから見える状況を元に仮説を立てて検証していくこともあるでしょう。

リクエストを受け付けるとなぜか応答を返さないままになってしまう gRPC サーバに対し、ソースから解析をかけていったことがありました。そのときは目の前の対応で必死になってしまいましたが、本エントリでは「本来はどのようにデバッグを進めるべきだったのか」を考えます。

結論としては、以下の 2 つを実施するのが王道だったのでしょう…。

• trace を取得する
• goroutine ダンプを取得する

実験コード

mutex の Unlock を忘れたサーバ

まずは駄目なサーバを用意します。 ここではシンプルに、グローバルな mutex の Unlock 忘れというシンプルな状況を作りました。 AcquireLock という RPC では、mu (sync.Mutex) を Lock したまま Unlock しません。

これにより、1 回目の AcquireLock 呼び出しだけは成功しますが、timeout を設定しない限り 2 回目以降の呼び出しはすべて mu.Lock() 行でハングします。

// AcuareLock acquires an global lock, and doesn't release it.
func (s *server) AcquireLock(ctx context.Context, req *empty.Empty) (*empty.Empty, error) {
    log.Println("acquiring an lock")
    mu.Lock()
    // defer mu.Unlock()
    log.Println("acquired.")
    return &empty.Empty{}, nil
}

同時並行して AcquireLock を呼び出すクライアント

AcquireLock を 10 並列で呼び出すクライアントを実装しました。 とりあえず 100 万個ほど goroutine を起動させ、10 並列で RPC を呼び出します。

   limit := make(chan struct{}, 10)
    var wg sync.WaitGroup
    for i := 0; i < 1000000; i++ {
        wg.Add(1)
        go func(i int) {
            limit <- struct{}{}

            log.Printf("acquireLock: %d", i)
            _, err := c.AcquireLock(context.Background(), &empty.Empty{})
            if err != nil {
                log.Fatalf("AcquireLock: %v", err)
            }
            wg.Done()
            <-limit
        }(i)
    }
    wg.Wait()

当然ながら、最初に AcquireLock を呼び出す goroutine のみが制御を戻し、以降の goroutine は hang するという形になります。

trace

これについては、最初に golang で標準的な形で trace の可視化をすると何がわかるのかを見ていただくのがわかりやすいです。

上記の画像は、作成した gRPC サーバの 10 秒間の trace を取得して、それを go tool trace にかけたものです。 簡単に言うと、trace をかけている期間について以下を見ることができます。

• heap
• goroutine 数
• OS thread 数
• OS thread 上で動作している goroutine の内容

デバッグに最も重要かなと個人的に感じているのは、どの OS thread 上で、どの goroutine がどこまで動いたのが可視化できるということです。

他にも、特定メソッドが各 goroutine でどういう実行をされたのかを見ることができます。

また、どのメソッドがどのメソッドを呼び出して、そのときの時間は…というようなことも視覚的に見ることができたりします。

trace の取得方法

サーバサイド

gRPC サーバのような永続プロセスで trace を取得するためにサーバで行うことは、 net/http/pprof パッケージを import した上で、HTTP サーバを立ち上げるだけです。

import _ "net/http/pprof"

// blah blah blah

func main() {
    // profile/trace 取得用 HTTP サーバの立ち上げ
      go func() {
        log.Println(http.ListenAndServe("localhost:6060", nil))
    }()

    // 実際の main 処理
}

net/http/pprof の初期化コードは以下のようになっています。import 時の副作用として、いくつかの trace/profile 取得用エンドポイントを定義してくれる仕組みです。

func init() {
    http.HandleFunc("/debug/pprof/", Index)
    http.HandleFunc("/debug/pprof/cmdline", Cmdline)
    http.HandleFunc("/debug/pprof/profile", Profile)
    http.HandleFunc("/debug/pprof/symbol", Symbol)
    http.HandleFunc("/debug/pprof/trace", Trace)
}

trace の可視化

この状況で trace を取得するためには、上記の HTTP サーバの trace 取得用エンドポイント /debug/pprof/trace に向けて、HTTP リクエストを送信してやれば良い。

$ curl -o grpc.trace 'http://localhost:6060/debug/pprof/trace?seconds=10'

trace を取得する期間を意味するのが、パラメータ seconds になります。 あとは、ここで取得した trace を go tool trace にかけるだけで、先程お見せした trace の可視化が実現できます。

$ go tool trace ./server ./grpc.trace

./server は、trace を取得した対象となるサーバプログラムのバイナリですが、確かこれはもう指定しなくても良いはずです。

trace からのデバッグ

trace によって、各 goroutine がどこまで動いて止まったのかまでわかります。 今回 gRPC method handler としての goutine は mu.Lock() まで動いて止まっているのが一目瞭然でした。

goroutine ダンプの取得

他にも、特定のタイミングで動いている全 goroutine のスタックトレースを取得することも可能です。テキストベースで取得できるので、こちらのほうが解析しやすい、なんて場合もあるのではないでしょうか。

$ curl -s 'http://localhost:6060/debug/pprof/goroutine?debug=2' | head -10
goroutine 9 [running]:
runtime/pprof.writeGoroutineStacks(0x1897b00, 0xc000192000, 0xc00012e420, 0x0)
        /usr/local/Cellar/go/1.12.4/libexec/src/runtime/pprof/pprof.go:679 +0xab
runtime/pprof.writeGoroutine(0x1897b00, 0xc000192000, 0x2, 0xc00012e440, 0xc00012e420)
        /usr/local/Cellar/go/1.12.4/libexec/src/runtime/pprof/pprof.go:668 +0x52
runtime/pprof.(*Profile).WriteTo(0x1ca5580, 0x1897b00, 0xc000192000, 0x2, 0xc000192000, 0x20)
        /usr/local/Cellar/go/1.12.4/libexec/src/runtime/pprof/pprof.go:329 +0x4fc
net/http/pprof.handler.ServeHTTP(0xc00018c011, 0x9, 0x18a0800, 0xc000192000, 0xc000128200)
        /usr/local/Cellar/go/1.12.4/libexec/src/net/http/pprof/pprof.go:245 +0x3b6
net/http/pprof.Index(0x18a0800, 0xc000192000, 0xc000128200)