はじめに

フューチャーAdvent Calendar 2019 の1日目です。

この記事ではGoのベンチマーク機能について書いていきます。

普段わたしは業務系アプリのサーバサイド開発でGoを利用しています。いままでの経験では性能的なボトルネックはGoで書いたアプリケーションロジック部分ではなく、外部のデータストア（RDBやらAWS DynamoDB）の問い合わせ部分であることが多かったのですが、何度か非常に低速なコードを書いてしまったことがあります¹。そういった場合にも対応できるよう、コードのどの部分が処理負荷が高いのか切り分けるようにGoのベンチマーク機能を調査した結果を残していきます。

Go Benchmark 概要

Goにはtestingというパッケージやユーティリティツール(CPUなどのプロファイリングなど)が標準機能として提供されています。基本形のテストは func TestXxx(*testing.T) という形式でテストコードを書いて、go test コマンドで実行できます。

ベンチマークのテストも同様に、 func BenchmarkXxx(*testing.B) という形式でテストコードを書いて、 go test -bench=. で実行できます。概略は公式ドキュメントのPackage testingに書いています。-bench 時に利用できるオプションは Testing flags にまとまっています。

オプションを見ると、なにげに多くの機能があることがわかりますが、今回はベンチマークの結果可視化部分を中心に見ていきます。

Benchmarkコードの準備

まずは何でも良いですが、ベンチマーク対象とする関数を用意します。

ベンチマーク対象のコード（どんな処理でも良いですが、今回は画像をリサイズする処理にしました）


import (
    "github.com/nfnt/resize"
    "image/jpeg"
    "os"
)

func ResizeJPEG(src, dest string, quality int) error {
    f, err := os.Open(src)
    if err != nil {
        return err
    }

    img, err := jpeg.Decode(f)
    if err != nil {
        return err
    }
    f.Close()

    out, err := os.Create(dest)
    if err != nil {
        return err
    }
    defer out.Close()

    m := resize.Resize(1000, 0, img, resize.Lanczos3)
    return jpeg.Encode(out, m, &jpeg.Options{
        Quality: quality,
    })
}

これに対応するベンチマークコードを準備します。比較のためJPEGのQualityを75, 100の2種類分用意しました。

import "testing"

func BenchmarkResizeJPEG_q75(t *testing.B) {
    err := ResizeJPEG("src.jpg", "resize_q75.jpg", 75)
    if err != nil {
        t.Fatal("resize src.jpg: ", err)
    }
}

func BenchmarkResizeJPEG_q100(t *testing.B) {
    err := ResizeJPEG("src.jpg", "resize_q100.jpg", 100)
    if err != nil {
        t.Fatal("resize src.jpg: ", err)
    }
}

このコードに対して go test -bench=. で実行します。

$ go test -bench=.
goos: windows
goarch: amd64
pkg: github.com/laqiiz/go-tooling-sample/thumbnail
BenchmarkResizeJPEG_q75-4       1000000000               0.0797 ns/op
BenchmarkResizeJPEG_q100-4      1000000000               0.138 ns/op
PASS

用意したベンチマーク関数ごとの、 実行回数 ・ 1回あたりの実行にかかった時間(ns/op) が取得できます。

ベンチマーク結果の可視化

さて、 go test -bench=. は非常に実行が簡単ですし、これだけで事足りることも多いと思います。一方でベンチマーク対象の関数そのものをチューニングしたい時には、ボトルネックが関数内のどこにあるか分かりにくいです。

そのため、逐次処理のトレースを行ってみます。トレース方法はまず -trace オプションで実行トレースを出力し、 go toolでビジュアライズします。

$ go test -bench=. -trace a.trace

これで a.trace というファイルが出力されていると思います。もし出力されていなければベンチマークテストが失敗している可能性があります。 a.trace にはゴルーチンの作成/ブロック/ブロック解除、システムコールの開始/終了/ブロック、GC関連のイベント、ヒープサイズの変更、プロセッサの開始/停止などの情報がバイナリ形式で書き込まれているそうです。詳細はPackage trace を参考ください。

この a.trace ファイルを引数にして、go tool traceを実行します。--http で起動するサーバのポートを指定する必要があります。

$ go tool trace --http localhost:6060 a.trace
2019/12/01 00:12:52 Parsing trace...
2019/12/01 00:12:52 Splitting trace...
2019/12/01 00:12:52 Opening browser. Trace viewer is listening on http://127.0.0.1:6060

そうすると、以下のようなページがブラウザで表示されます。

ここから1番トップの View traceを見ると下記のようなグラフを表示できます。

内容は横軸は時間で、GCやコアごとの利用率がわかります。ボックスをドラッグすると拡大・縮小できるため気になるところをピンポイントで拡大できるので、ボトルネックになっていそうなところはこちらで確認します。

Zoom In/Outでベンチマーク対象の関数が呼び出している resizeパッケージの実行時間などがわかります。今回は自分で書いたコードが殆ど無いですが、他にも複数のパッケージ呼び出しがあるような関数をベンチマークした時は処理時間の内訳が分かるのではないでしょうか。

CPUプロファイリング

続いて、同じベンチマークコードに対してCPUプロファイルを行います。CPUプロファイリングは、比較的ランタイム負荷が小さい処理で、実行中のgorutineのコールトレースを収集することで分析を行います。

trace の場合と同様に、-cpuprofile オプションで同様に.prof ファイルが出力されますのでまずベンチマークのテストを実行します。

$ go test -bench=. -cpuprofile a.prof
goos: windows
goarch: amd64
pkg: github.com/laqiiz/go-tooling-sample/thumbnail
BenchmarkResizeJPEG_q75-4       1000000000               0.0779 ns/op
BenchmarkResizeJPEG_q100-4      1000000000               0.0920 ns/op
PASS
ok      github.com/laqiiz/go-tooling-sample/thumbnail   3.141s

出力された a.prof に対して、 go tool pprof を実行して可視化します。

$ go tool pprof -http :6060 a.prof
Serving web UI on http://localhost:6060

※可視化には Graphviz が必要です。未インストールの方はこちらから環境構築ください

Graphvizがインストールされた端末のブラウザで http://localhost:6060/ui/ を確認すると、以下のようなコールグラフが出力されています。

処理が重そうな部分は強調して表示されているようなのでわかりやすいですね。グラフをみると、resizeの処理に隠れていますがjpegのDecodeや、jpegのEncode（書き込み）部分も処理が重いことがわかります。

Viewタブから「Frame Graph」を選択すると以下のようなフレームグラフも表示できます。
人によってはこちらのほうが理解しやすいかも知れません

これらのグラフによって、もしこのベンチマーク対象の関数をチューニングしようとする時は、resize処理だけではなく、DecodeやEncodeを別処理として非同期に切り出すような選択や、上手くバッチ的に処理できないかといったアプローチを検討する判断材料にもなると思います。

まとめ

Goのベンチマークといえば、関数のマイクロベンチマークのためのツールで、関数内部のプロファイルを行う機能は無いと思っていましたが、既存のToolセットと合わせることが可視化分析も可能でした。

「ボトルネックになっていない箇所を最適化しようとするのは自転車置き場議論だ！」とGoogle Cloud Next ’19 in Tokyoのあるセッションで聞いたのですが、Go Toolingも活用して推測ではなく事実をベースにチューニングしていきたいですね。

例えば、GPSの緯度経度から地域メッシュコードを特定する処理などです ↩

Go Benchmark Toolingで実行結果の可視化機能を利用する

はじめに

Go Benchmark 概要

Benchmarkコードの準備

ベンチマーク結果の可視化

CPUプロファイリング

まとめ