はじめに

失敗談をテーマにした連載の3本目です。

TIG DXユニットの原です。21年度4月に新卒で入社し、2年目となります。

参加しているプロジェクトで、数百万件のデータを処理する機能を担当したことがありました。

本記事はその際の失敗と、その失敗から得た経験を共有するため、執筆しました。

内容のサマリ

本来フィールドで宣言すべき定数的に扱いたい変数を、関数内で毎回生成しreturnしてしまったので呼び出す度に毎回アロケートが発生し性能劣化してしまった
Benchmark Test、Profiling、Escape Analysisでどのような挙動になってしまっていたか調べてみた

内容

本記事では、まずどのような状況であったかを説明し、どのような順番で問題を解決したかの順で説明します。

主にGoのテストとProfilingに関した内容です。

Goのテストについての関連記事として、Goのテストに入門してみよう！とGo 1.17のtesting新機能があります。
ぜひ確認ください！

問題状況

処理する数百件のデータについて、マスタ情報から情報を引き出す必要がありました。

その際に、マスタデータをDBに置いとくとDBへの接続が発生するため、map型でハードコーディングすることにしました。

そして、他の個所でマスタ情報の変更ができないようにGetterを作りました。
(Go言語では、map型はconstができないため、Getterにするしかありませんでした、、)

それで最初に作成したコードが下記のような感じです。

package master

type MasterRecordstruct {
Doublestring
Triplestring
}

// Example code of problem setting
funcGetMaster1()map[int]MasterRecord {
returnmap[int]MasterRecord{
0:   {Double:"００", Triple:"０００"},
1:   {Double:"１１", Triple:"１１１"},
...
498: {Double:"４９８４９８", Triple:"４９８４９８４９８"},
499: {Double:"４９９４９９", Triple:"４９９４９９４９９"},
}
}

その結果、数百件のデータを処理するためには、数時間がかかる性能問題が発生しました。

問題箇所の特定

最初は、問題個所の特定ができなかったため、問題の箇所を特定するために、機能ごとのBenchmark Testを書くことにしました。

Benchmark Test

Go言語では、テスト作成の際に性能の観点でのテストができるBenchmark Testを提供しています。
Benchmark Testは、*testing.Bの引数を持つBenchmarkで始まるテストメソッドを作ることで作成できます。

package master_test

...
// BenchmarkGetMaster Benchmark Test for GetMaster1
funcBenchmarkGetMaster1(b *testing.B) {
for i :=0; i < b.N; i++ {
master.GetMaster1()
}
}
...

Benchmark Test Result

テストの実行は-benchオプションと-benchmemつけてテストを実行するだけでできます。

$ gotest -v -bench . -benchmem playground/master
goos: windows
goarch: amd64
pkg: playground/master
cpu: Intel(R) Core(TM) i7-5700HQ CPU @ 2.70GHz
...
BenchmarkGetMaster1
BenchmarkGetMaster1-8               5713            207556 ns/op          210712 B/op       1021 allocs/op
...
ok      playground/master       3.911s

上記のテスト結果を見ると、BenchmarkGetMasterを5713反復したら、平均的に207556 ns/opの実行速度と210712 B/op・1021 allocs/opのメモリアロケーションが発生していることが分かります。

ほかの機能と比較して、実行速度が顕著に遅かったため、マスタデータのGetterが性能問題の原因であると特定できました。そしてその原因は、想定外の大量のメモリアロケーションが発生しているからだと推測できます。

メモリアロケーションの原因特定

メモリアロケーションの原因を特定するためには、ProfilingとEscape Analysisを利用しました。

Profiling

Go言語では、標準的にProfiling機能提供しています。Profilingは-cpuprofileと-memprofileオプションを用いてできます。

Profiling Test Code

$ gotest -v -cpuprofile cpu.prof -memprofile mem.prof -bench . -benchmem playground/master
goos: windows
goarch: amd64
pkg: playground/master
cpu: Intel(R) Core(TM) i7-5700HQ CPU @ 2.70GHz
...
BenchmarkGetMaster1
BenchmarkGetMaster1-8               5713            207556 ns/op          210712 B/op       1021 allocs/op
...
PASS
ok      playground/master       3.911s

Profiling結果の確認

-cpuprofileでは、CPUの処理時間ベースのProfilingが、-memprofileメモリベースのProfilingができます。その結果はgo tool pprofコマンドで確認できます。

$ go tool pprof -http :8080 cpu.prof
Serving web UI on http://localhost:8080

すると、下記のようにProfilingの結果を確認できます。

私が想像したのは、固定のmap型のデータを返すような単純な処理図を予測していましたが、ものすごく複雑な結果を得ました。

Escape Analysis

なんでこんなに複雑になったかを把握するため、Escape Analysisを適用してみました。Escape Analysisは、go buildする際に-gcflags '-m'オプションを追加することでできます。

$ go build -gcflags'-m' master/mater1.go
# command-line-arguments
master\mater1.go:4:34: map[int]map[string]string{...} escapes to heap
master\mater1.go:5:8: map[string]string{...} escapes to heap
master\mater1.go:6:8: map[string]string{...} escapes to heap
...
master\mater1.go:503:8: map[string]string{...} escapes to heap
master\mater1.go:504:8: map[string]string{...} escapes to heap

その結果、GetterをするたびにHeapメモリにエスケープが発生していることが分かりました。すなわち、Getterが呼ばれるたびに、mapデータを作っていたわけです。

問題の解決

Getterが呼ばれるたびに、mapを生成することが問題であるため、mapデータをパッケージ変数として定義し、Getterではその変数を返すようにすることで、mapの再生成は抑えることができました。

その結果最初数時間かかる数百万件データの処理速度も、数十秒レベルで終わらせることができました。

package master

var m =map[int]MasterRecord{
0:   {Double:"００", Triple:"０００"},
1:   {Double:"１１", Triple:"１１１"},
...
498: {Double:"４９８４９８", Triple:"４９８４９８４９８"},
499: {Double:"４９９４９９", Triple:"４９９４９９４９９"},
}

funcGetMaster2()map[int]MasterRecord {
return m
}

もとの変数mが直接呼び出し元に渡るため、呼び出し元でmapを直接操作して書き換えると、全体に影響を受けます。これを避けるために、アクセスをキー指定必須にするといったことも検討できると思います。

// GetMaster2() は非公開のみとし、ID指定の関数のみパッケージエクスポートする
funcGetMasterByID(idstring) MasterRecord {
return m[id]
}

今回の要件ですとマスタ（map）を駆動に処理をしたい処理があったこと。トレードオフはあるものの、書き換えはコードレビューで担保することとし、GetMaster2()方式で対処しました。

比較

Getterでmapデータを生成していたGetMaster1と、パッケージ変数を返しているGetMaster2を比較してみました。

GetMaster1とGetMaster2のBenchmark Test結果

その結果は明らかで、パッケージ変数を返しているGetMaster2ではメモリアロケーションが発生してなく、処理速度も数十万倍速くなりました。

$ gotest -v -cpuprofile cpu.prof -memprofile mem.prof -bench . -benchmem playground/master
goos: windows
goarch: amd64
pkg: playground/master
cpu: Intel(R) Core(TM) i7-5700HQ CPU @ 2.70GHz
BenchmarkGetMaster1
BenchmarkGetMaster1-8               5172            206772 ns/op          210720 B/op       1021 allocs/op
BenchmarkGetMaster2
BenchmarkGetMaster2-8           1000000000               0.2957 ns/op          0 B/op          0 allocs/op
PASS
ok      playground/master       1.639s