Day 038 — pprofによるプロファイリング①（CPU）（実践: 非効率アルゴリズムのCPUプロファイル取得と特定）

📚 背景知識（読んでから問題へ）

Day 036・037では、-gcflags="-m"（エスケープ解析）と-benchmem（アロケーション実測）を使って、「このコードは実行前からどんな性質を持つか」を静的に予測する方法を学びました。しかし実際の本番システムでボトルネックになっているのは、多くの場合「予測していなかった箇所」です。ソースコードを読んだだけでは、どの関数がCPU時間の大半を消費しているかは正確にはわかりません。ここでDay 038から扱うpprof（Profile + prof）は、実際に動いているプログラムを観測して、実測データからボトルネックを特定するためのツールです。

プロファイル結果を読むときに重要な2つの指標があります。

• flat（自己時間）: その関数自身のコードが実行されていた時間（他の関数呼び出し先で消費した時間は含まない）
• cum（累積時間、cumulative）: その関数、およびその関数が呼び出した先すべてで消費された時間の合計

📝 問題

以下は、「指定した上限未満の素数の個数を数える」バッチ処理プログラムです。機能的には正しいですが、大きな上限を指定すると著しく遅くなります。

📋 コピーpackage main

import (
	"flag"
	"fmt"
	"os"
	"runtime/pprof"
)

// isPrimeSlow は n が素数かどうかを、2からn-1まで愚直に試し割りして判定する
func isPrimeSlow(n int) bool {
	if n < 2 {
		return false
	}
	for i := 2; i < n; i++ {
		if n%i == 0 {
			return false
		}
	}
	return true
}

func countPrimes(limit int) int {
	count := 0
	for i := 2; i < limit; i++ {
		if isPrimeSlow(i) {
			count++
		}
	}
	return count
}

func main() {
	cpuprofile := flag.String("cpuprofile", "", "write cpu profile to file")
	flag.Parse()

	if *cpuprofile != "" {
		f, err := os.Create(*cpuprofile)
		if err != nil {
			fmt.Fprintln(os.Stderr, "could not create CPU profile:", err)
			os.Exit(1)
		}
		defer f.Close()
		if err := pprof.StartCPUProfile(f); err != nil {
			fmt.Fprintln(os.Stderr, "could not start CPU profile:", err)
			os.Exit(1)
		}
		defer pprof.StopCPUProfile()
	}

	n := countPrimes(200000)
	fmt.Println("primes found:", n)
}

要件

1. 上記コードをgo run main.go -cpuprofile=cpu.profで実行し、CPUプロファイルを取得する手順（ビルド〜実行〜go tool pprofでの確認）を具体的なコマンド列で示す
2. go tool pprof -top cpu.profを実行した場合にどの関数がflat時間の大半を占めると予測されるか、コードの構造から論理的に説明する
3. list isPrimeSlow（あるいは該当関数）で行単位の内訳を見た場合、どの行が最もコストを支配していると予測されるかを、アルゴリズムの計算量の観点から説明する
4. countPrimesのアルゴリズムを、外部から見た戻り値（見つかった素数の個数）を変えずに、計算量を落とす形に書き直す（エラトステネスの篩を使うこと）。go run main.goでそのまま動く完全なコードを提示すること
5. 修正前後でgo tool pprof -topの出力がどう変わると予測されるか、またgo test -bench . -cpuprofile=cpu.profを使ってベンチマーク実行中のプロファイルを取得する場合のテストコードとコマンドを示す
6. CPUプロファイリング（時間の消費）とDay 037で扱ったアロケーションプロファイリング（-benchmem・-memprofile）は、それぞれ何を計測し、何を計測できないかを整理する

🔍 ヒント（段階的開示）

📋 コピーmkdir day038 && cd day038
go mod init example.com/day038
# main.go に上記コードを保存する
go build -o day038bin .
./day038bin -cpuprofile=cpu.prof
# primes found: XXXXX が出力され、cpu.prof が生成される

go tool pprof -top cpu.prof
# (pprof) top コマンドを実行した状態と同じ出力が得られる
# 上位に isPrimeSlow が flat 90%以上を占める形で出るはずである

go tool pprof cpu.prof
# 対話モードに入ったら以下を試す
# (pprof) list isPrimeSlow
# (pprof) top10
# (pprof) web    ← Graphvizが入っていればコールグラフをブラウザ表示

✅ 模範解答

1. CPUプロファイル取得の手順

📋 コピー# 1. モジュール初期化とビルド
mkdir day038 && cd day038
go mod init example.com/day038
# main.go に問題文のコードを保存

# 2. -cpuprofile フラグを付けて実行し、プロファイルを取得する
go build -o day038bin .
./day038bin -cpuprofile=cpu.prof
# 標準出力: primes found: 17984
# カレントディレクトリに cpu.prof が生成される

# 3. go tool pprof でトップの関数を確認する
go tool pprof -top cpu.prof

go tool pprof -top cpu.profの出力イメージ（実測値は環境依存だが、傾向はほぼ確実に以下のようになります）:

📋 コピーShowing nodes accounting for 1.98s, 99.50% of 1.99s total
      flat  flat%   sum%        cum   cum%
     1.85s 92.96% 92.96%      1.97s 98.99%  main.isPrimeSlow
     0.12s  6.03% 98.99%      1.97s 98.99%  main.countPrimes
     0.01s  0.50% 99.50%      1.99s 100%    main.main

2. flat時間の大半を占める関数の予測

isPrimeSlowが圧倒的にflat時間の大半（90%超）を占めると予測できます。理由は次の通りです。

• countPrimesはisPrimeSlowを呼び出す「ループの外枠」に過ぎず、それ自体の計算（呼び出しとカウントのインクリメント）は軽量
• isPrimeSlowは最悪O(n)回のループを内部に持ち、これがlimit回（=200000回）呼び出される。関数自身のループ本体でCPU時間を消費しているため、他の関数を呼び出さないisPrimeSlowはflatとcumがほぼ一致するという特徴も予測できる（子関数を呼んでいないため、cumに上乗せされる分がほとんどない）

3. isPrimeSlow内でコストを支配する行

📋 コピーfor i := 2; i < n; i++ {
    if n%i == 0 {   // ← ここが最もコストを支配する行
        return false
    }
}

list isPrimeSlowを実行すると、n%i == 0を含む行に最も多くの時間が計上されると予測できます。理由は次の2点です。

1. ループの条件式i < nの評価とインクリメントi++は毎回実行されるが、それ自体は軽量な整数演算である
2. モジュロ演算n%iは整数除算命令であり、加算・比較よりも相対的にコストが高い。しかもこのループの各反復で必ず1回実行されるため、ループの実行回数（nに依存）にほぼ比例して行全体のコストが積み上がる

nが合成数でない限り（＝素数である場合）、このループはn-2回すべて回り切ります。大きい素数を判定するたびに最悪ケースを踏むため、素数が多く含まれるlimit未満の範囲では特にコストが支配的になります。

4. エラトステネスの篩による書き直し

📋 コピーpackage main

import (
	"flag"
	"fmt"
	"os"
	"runtime/pprof"
)

// countPrimesSieve はエラトステネスの篩により、limit未満の素数の個数を数える。
// isPrimeSlow を使う旧実装(O(limit^2))と異なり、O(limit log log limit) で完了する。
func countPrimesSieve(limit int) int {
	if limit < 2 {
		return 0
	}
	composite := make([]bool, limit)
	count := 0
	for i := 2; i < limit; i++ {
		if composite[i] {
			continue
		}
		count++
		// i の倍数(i*iから開始)をすべて合成数として印を付ける
		for j := i * i; j < limit; j += i {
			composite[j] = true
		}
	}
	return count
}

func main() {
	cpuprofile := flag.String("cpuprofile", "", "write cpu profile to file")
	flag.Parse()

	if *cpuprofile != "" {
		f, err := os.Create(*cpuprofile)
		if err != nil {
			fmt.Fprintln(os.Stderr, "could not create CPU profile:", err)
			os.Exit(1)
		}
		defer f.Close()
		if err := pprof.StartCPUProfile(f); err != nil {
			fmt.Fprintln(os.Stderr, "could not start CPU profile:", err)
			os.Exit(1)
		}
		defer pprof.StopCPUProfile()
	}

	n := countPrimesSieve(200000)
	fmt.Println("primes found:", n)
}

i*iから開始できるのは、i未満の倍数（2*i, 3*i, ..., (i-1)*i）はすでにそれより小さい素数の倍数として印付け済みだからです。これにより無駄な再走査を避けられます。countPrimes（旧実装）とcountPrimesSieve（新実装）はlimit=200000に対して同じ17984という個数を返します（外部から見た戻り値は不変）。

5. 修正前後のプロファイル比較とベンチマーク実行時のプロファイル取得

プロファイルの変化予測:

修正前はisPrimeSlowがflat%のほぼ全てを占めていましたが、修正後はcountPrimesSieve自体（篩の二重ループ）に時間が分散し、かつ全体の実行時間そのものが大幅に短縮されるため、同じサンプリング間隔（10ms）でも記録されるサンプル数自体が激減します。プログラムが速すぎてサンプルがほとんど採れない場合は、limitを大きくする（例: 2000000）か、ループで複数回呼び出してから計測するのが実務上の定石です。

ベンチマークでのプロファイル取得:

📋 コピー// main_test.go
package main

import "testing"

func BenchmarkCountPrimesSieve(b *testing.B) {
	for i := 0; i < b.N; i++ {
		countPrimesSieve(200000)
	}
}

📋 コピーgo test -bench BenchmarkCountPrimesSieve -cpuprofile=cpu.prof -benchtime=3s
go tool pprof -top cpu.prof

go testが-cpuprofileフラグをネイティブでサポートしているため、runtime/pprofを手動で呼ぶコードを書かなくても、テストバイナリの実行区間全体のCPUプロファイルを取得できます。ベンチマーク駆動でボトルネックを特定する際は、main関数に計測コードを埋め込むよりもこちらの方法が簡潔です。

6. CPUプロファイリングとアロケーションプロファイリングの違い

🪜 Step-by-Step 解説

💡 設計思想・なぜこう書くのか

🌐 他言語との比較

🏆 実務での使いどころ

• 本番障害・レイテンシ悪化の原因調査: net/http/pprofを有効化しておけば、レイテンシが悪化したタイミングでcurl一発でCPUプロファイルを取得し、後からgo tool pprofで解析できる
• リリース前のパフォーマンスレビュー: 新機能追加後にgo test -bench . -cpuprofile=cpu.profを実行し、想定外のホットスポットが生まれていないかを確認する
• 「推測ではなく実測」の文化づくり: 「ここが遅そう」という勘に頼った最適化ではなく、top・listの実測データに基づいて優先順位をつけることで、無駄な最適化作業を避けられる
• アルゴリズム選定の説得材料: エラトステネスの篩のような教科書的な計算量改善が、実際にプロファイル上で「flat時間が劇的に減る」形で裏付けられることを、コードレビューやチーム内共有で示せる

⚠️ よくある誤解・ミス

🚀 次のステップ

• 発展: day038のコードにgo tool pprof -http=:8080 cpu.profを実行し、ブラウザ上のFlame Graph（フレームグラフ）でコールスタックの積み上げを視覚的に確認してみましょう。topのテキスト出力だけでは掴みにくい「呼び出し階層の広がり」が一目でわかります
• 次回予告: pprofによるプロファイリング②（メモリ） — Day 039では、Day 037で静的に予測した「隠れたヒープ割当」を、-memprofileとgo tool pprofのalloc_objects/inuse_spaceビューを使って実測データから特定する方法を学びます

🎯 自己評価

自分の回答

気づき・メモ