Goの並列処理でパフォーマンスが上がらない原因をpprof,runtime/traceで調べてみる
この記事の概要
先日神戸でGo workshop conference 2025というのが開催されており、そこに参加してきました。
その際以下2つのworkshopに参加したのですが、午前の部でなぜか自分だけ並列処理のパフォーマンスが上がらないという事象に出くわしました。
その場では原因がわからずコードも正解のものをコピペしているのに改善されないといったところで個人的な環境に問題がありそうだったので帰宅後改めて調べてみることにしました。
調べるにあたって、せっかくなので午後参加したworkshopで学んだpprofとruntime/traceを使って問題箇所を絞り込んでみようと思いました。
結果的に期待するところまで処理速度が改善できたので、そこに至るまでの流れをここでまとめておこうと思います。
想定している読者
pprof, runtime/traceを使ったパフォーマンス調査・改善手順を知りたい方。
そもそもの課題
今回問題になったのは、以下午前の部で作成した200個のファイルをgoroutineで並列処理するという課題がありました。
本来であれば、逐次処理で20秒弱かかっていたのが並列処理にすることで5秒前後になるというのが想定される挙動でしたし自分以外の参加者はそうなっていました。
しかし実際には自分は60秒以上かかっており悪化していました。
=== 処理結果 ===
処理時間: 68.89秒
総リクエスト数: 10,000,000件
並列化すれば性能が上がるわけではない典型例を体験できたのはそれはそれで学びだったなと思います。
分析方法
一体何がボトルネックになってこんなに処理に時間がかかってしまっているのでしょうか。
今回は午後の部で以下のようなプロファイリングに関するWorkshopも受けていたので、これらを使えば原因を特定できるのでは？と思い立った次第です。
具体的には、以下手順で分析をしていきました。
- pprofでプロファイリングができるので、おおまかな原因をそれで把握する。
- runtime/traceで具体的にどういったイベントが発行されているかを見てボトルネックを特定する。
実際に分析してみる
profileとは
pprofを使えば、CPU, Heap, Goroutineの使用状況などをサンプリングした統計情報として確認することができる。
pprof Setup
まずはpprofでreportを収集するための実装をmainの最初に追加します。
pprofを使うためには計測のための実装が必要で、用途によって使い分けます。
- runtime/pprof: CLIツールなど用
- net/http/pprof: HTTPサーバのプロファイルを取りたい場合
以下コードを埋め込んで実行すると、cpu.profが生成されます。
func main() {
// CPU Profile作成
report, _ := os.Create("cpu.prof")
defer report.Close()
_ = pprof.StartCPUProfile(report)
defer pprof.StopCPUProfile()
// ...main処理
}
GUIでプロファイリング結果確認
cpu.profファイルが生成されるのでそれを参照してGUIツールで表示する。
go tool pprof -http :9999 cpu.prof
どうやらjsonのDecodeでかなりCPU使用時間を逼迫していそうです。
見方について
そもそもの上記項目の見方としては、以下である。
- Flat : 関数が内部で呼び出している他メソッドのリソース使用時間を除いた単体の時間。
- Cum: 内部での別関数の呼び出しも含めたリソース使用時間。
ここから読み取れることは、
- syscall.syscallがCPU使用のほとんどを占めている。（がsyscallがどこから呼ばれているのかは不明）
- 明らかに、encoding/json.(*Decoder).readValueが怪しい。
といったところでしょうか。ひとまず当たりをつけられたらCPU ProfileはOKです。（というかそれ以上の細かいところまでは分からないのがProfileの限界とWorkshopの人も言ってた）
次にTraceでより細かいところを確認する。
Runtime/Trace Setup
次にtraceを収集します。Traceとは、すべてのイベント結果を時系列順に取得する情報のこと。
基礎概念
- task
- 例: mainでmain taskを定義する
- region
- 例: mainから呼び出されるf()関数内で定義する￥
こちらもセットアップが必要で、今回は以下のような実装を行いました。
trace.NewTask でTrace対象のグループみたいなものを作成して、そこから生成されたcontextを使って対象メソッド内でRegionの設定をするような使い方をするらしいです。
func main() {
// traceファイル作成
f, err := os.Create("tseq.out")
if err != nil {
log.Fatalln("Error:", err)
}
defer func() {
if err := f.Close(); err != nil {
log.Fatalln("Error:", err)
}
}()
// trace開始
if err := trace.Start(f); err != nil {
log.Fatalln("Error:", err)
}
defer trace.Stop()
ctx, task := trace.NewTask(context.Background(), "計測したい問題の関数")
defer task.End()
results := 計測したい問題の関数(ctx)
//...main処理
}
func 計測したい問題の関数(ctx context.Context) {
defer trace.StartRegion(ctx, "計測したい問題の関数").End()
// ...処理
}
Runtime/Trace GUIで分析
上記のようにすることで、UserDefined Taskページでタスク単位で分析ができるようになります。
User-defined regionsをクリックすると以下に遷移できる。
- Count: goroutineの数
- Duration distribution (complete tasks): 処理時間の分布。39秒かかったgoroutineが135個ほどで25秒程度のgoroutineが30個ほどだったという分布になっている。
上記の39.81~をクリックすると各goroutineが何に時間を使っていたかを見ることができます。
各項目の意味としては以下のようになっており、**Block time (syscall)**が明らかにボトルネックであることがわかります。
| 項目 | 説明 |
|---|---|
| Execution time（赤） | 実際に CPU 上で Go のコードを実行していた時間 いわゆる「純粋な実行時間」 |
| Block time (GC mark assist wait for work) | GC の mark assist による待ち 割り当てが多い／ヒープ圧が高いと増える |
| Block time (chan receive) | チャネル受信待ち<-ch でブロックしていた時間producer が遅い／詰まっていると増える |
| Block time (sync) | mutex / RWMutex / Cond / WaitGroup 等の待ち ロック競合の代表指標 ここが大きい＝並列度が下がっている |
| Block time (syscall) | syscall 実行中でブロックしていた時間 例：ファイル I/O、ネットワーク I/O 今回はここが約40秒と長く、ネットワーク通信がないためファイル I/O 待ちと推測できる |
| Sched wait time | 実行可能だが、CPU が割り当てられるのを待っていた時間 GOMAXPROCS 不足／goroutine 過多の兆候 |
| Syscall execution time | 実際に syscall を実行していた CPU 時間Block time (syscall) とは別で、こちらはカーネル内で動いていた時間 |
ひとまずsyscallによるI/Oがボトルネックになっていることがわかった。
次に一つ一つのgoroutine Timelineを見て分析を進める。
上記では大量のsyscallが遅延していることが分かる。また、一つ前の状況から見ても他のCPUなどの部分で問題があるようには見えない。
こういった総合的な情報をChatGPTに投げてみました。そうすると過剰並列化が原因の可能性を上げてくれたので、以下のような対応をして並列度を下げてみました。
対策
以下のような実装を追加することで、並列度を抑えて実行することができました。
func 計測したい問題の関数(ctx context.Context) {
// 並列数を制限(例: 10)
const maxConcurrent = 10
sem := make(chan struct{}, maxConcurrent)
//...
// 各ファイルに対してgoroutineを起動
for _, data := range datas {
wg.Add(1)
go func() {
defer wg.Done()
// セマフォを取得(空きがなければブロック)
sem <- struct{}{}
defer func() { <-sem }() // 完了時に解放
// ...処理
}()
}
// ...処理
}
結果本来想定していた時間に改善できました。
=== 処理結果 ===
処理時間: 5.01秒
総リクエスト数: 10,000,000件
結果：並列度を上げすぎてうまく行かなかった。
課題自体は解決しましたがそもそもの環境要因的な部分までは結局分からず以下疑問は残ったままとなりましたので、今後の課題としようかなと思います。
- なぜ他の人はsyscall×200で問題なかったのに自分のPCではうまくいかなかったのか？
- 並列度はどこまで上げていいのか？それは何を見れば予測できる？
感想
Workshop形式だったので机を向き合わせて一部は行ったのですが、こうやるとお互いの顔をよく覚えられていいなと思いました。
Discussion