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

# はじめに

[フューチャーAdvent Calendar 2019](https://qiita.com/advent-calendar/2019/future) の1日目です。

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

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

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


# Go Benchmark 概要

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

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

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

# Benchmarkコードの準備

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

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

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種類分用意しました。

```go
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=.` で実行します。

```sh
$ 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でビジュアライズします。

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

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

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

```sh
$ 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
```

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

![Trace viewer top page](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/6463/3f065f72-7b1c-6f44-ff76-d1adec6baf18.png)

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

![view trace page](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/6463/1f05dfdd-d501-a6b9-09a5-ca64cd0dbd21.png)

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

![view trace page zoom in/out](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/6463/42353250-9917-c0bf-756e-92f71ee190df.png)

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

![resize部分.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/6463/c07ff17b-5b60-4a0c-22b0-a9f9e6c62cca.png)


# CPUプロファイリング

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

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

```sh
$ 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` を実行して可視化します。

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

**※可視化には `Graphviz` が必要です。未インストールの方は[こちら](https://www.graphviz.org/download/)から環境構築ください**

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

![cpu_profile.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/6463/848bd422-a405-7ab2-ffbf-479d03582385.png)

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

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

![framegraph.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/6463/435cdbbd-dc77-16b5-7809-2311531cf6a8.png)

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


# まとめ

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

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