step02

STEP 2: ボトルネックを探す

トレースを行う

STEP 1で作成したプログラムはなんとなく遅い気がします。 STEP 2では、runtime/traceパッケージを用いてトレースし、ボトルネックとなる部分を探します。

まずは、main関数をトレースするために、main関数の中身を_main関数に移動させます。

そして、トレース対象の処理を開始する前に、trace.Start関数を呼び出し、終了後にtrace.Stopを呼び出します。 なお、deferを用いることで、関数の終了時に呼び出すことができます。

func main() {
	f, err := os.Create("trace.out")
	if err != nil {
		log.Fatalln("Error:", err)
	}
	defer func() {
		if err := f.Close(); err != nil {
			log.Fatalln("Error:", err)
		}
	}()

	if err := trace.Start(f); err != nil {
		log.Fatalln("Error:", err)
	}
	defer trace.Stop()

	_main()
}

ユーザアノテーション

Go1.11からユーザアノテーションという機能が入りました。 ユーザが任意のタイミングでトレース情報を出力することができる機能です。

ユーザアノテーションは、以下の単位で行うことができます。

• Task
• Region
• Log

1つのTaskに複数のRegionがあり、Regionの中でLogを出すというイメージです。

ここでは、Taskは「コーヒーを淹れること」、Regionは「お湯を沸かす」、「豆を挽く」、「コーヒー淹れる」の3つになります。

Taskは次のように作成することができます。 作成したTaskは、Endメソッドを呼び出すまでの処理が対象となります。 通常はdeferで呼び出すことで関数の終了時に呼び出します。

ctx, task := trace.NewTask(context.Background(), "make coffee")
defer task.End()

trace.NewTask関数の第1引数で返されるcontext.Context型の値には、Taskの情報が保持されています。

Regionは次のように、trace.StartRegionを呼び出すことで作ることができます。 trace.StartRegionの第1引数にtrace.NewTask関数で返ってきたcontext.Contextを渡すことで、TaskとRegionを紐付けることができます。

作成したRegionは、Endメソッドを呼び出すまでの処理が対象となります。

region := trace.StartRegion(ctx, "region_name")
defer region.End()

なお、次のように1行で書くこともできます。

defer trace.StartRegion(ctx, "region_name").End()

実行とトレースデータの表示

TODOを埋めると次のコマンドで実行することができます。

$ go run main.go

trace.outというトレース情報を記録したファイルが出力されるため、次のコマンドで結果を表示します。

$ go tool trace trace.out

ブラウザが開くので、User-defined tasks -> Count -> Task 1の順番で開くと次のような結果が表示されれば成功です。

図を見ると、boil、grind、brewが直列に処理されていることがわかります。 boilとgrindは同時に行っても問題ないので、ここを改善すれば早くなりそうです。