Day 039 — pprofによるプロファイリング②（メモリ）（実践: 文字列連結によるアロケーション過多の特定）

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

Day 038ではruntime/pprofのCPUプロファイルを使い、「どの関数がCPU時間を消費していたか」を実測データから特定しました。Day 039で扱うのは同じpprofのもう一つの柱、メモリ（ヒープ）プロファイルです。

Day 037では-gcflags="-m"（エスケープ解析）を使って、「このコードのどの値がヒープに逃げるか」をコンパイル時に静的に予測しました。しかしエスケープ解析は「逃げるかどうか」を教えてくれるだけで、「実際に何バイト・何回、どのくらいの頻度でアロケーションが発生しているか」までは教えてくれません。それを実行時に実測するのが、runtime/pprofのWriteHeapProfileとgo tool pprofです。

go tool pprofはデフォルトでinuse_spaceを表示します。累積のアロケーション量を見たい場合は明示的に-alloc_space（または-alloc_objects）を指定する必要があります。

📝 問題

以下は、n行分のログ行を結合して1つのレポート文字列を作るバッチ処理プログラムです。機能的には正しいですが、大きなnを指定すると著しく遅く、かつ大量のメモリを消費します。

📋 コピーpackage main

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

// buildReportSlow は n 行分の行を文字列連結(+=)で結合してレポートを生成する
func buildReportSlow(n int) string {
	report := ""
	for i := 0; i < n; i++ {
		report += "line " + strconv.Itoa(i) + ": some log data here\n"
	}
	return report
}

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

	report := buildReportSlow(50000)
	fmt.Println("report length:", len(report))

	if *memprofile != "" {
		f, err := os.Create(*memprofile)
		if err != nil {
			fmt.Fprintln(os.Stderr, "could not create memory profile:", err)
			os.Exit(1)
		}
		defer f.Close()
		runtime.GC() // スナップショット前にGCを走らせ、inuseの値を正確にする
		if err := pprof.WriteHeapProfile(f); err != nil {
			fmt.Fprintln(os.Stderr, "could not write memory profile:", err)
			os.Exit(1)
		}
	}
}

要件

1. 上記コードをgo run main.go -memprofile=mem.profで実行し、メモリプロファイルを取得する手順（ビルド〜実行〜go tool pprofでの確認）を具体的なコマンド列で示す。-alloc_spaceと-inuse_space（デフォルト）の使い分けにも触れること
2. go tool pprof -top -alloc_space mem.profを実行した場合にどの関数がalloc_spaceの大半を占めると予測されるか、コードの構造から論理的に説明する
3. -alloc_spaceで見た総アロケーションバイト数と、-inuse_spaceで見たスナップショット時点の生存バイト数が大きく乖離すると予測される理由を、Goの文字列の不変性とGCの動作の観点から説明する
4. buildReportSlowのアルゴリズムを、外部から見た戻り値（生成されるレポート文字列）を変えずに、アロケーション回数を削減する形に書き直す（strings.Builderを使うこと）。go run main.goでそのまま動く完全なコードを提示すること
5. 修正前後でgo tool pprof -alloc_spaceの出力がどう変わると予測されるか、またgo test -bench . -memprofile=mem.profを使ってベンチマーク実行中にメモリプロファイルを取得する場合のテストコードとコマンドを示す
6. Day 037で扱った-gcflags="-m"による静的なエスケープ解析予測と、本問のようなruntime/pprofによる動的なメモリプロファイリングは、それぞれ何がわかり何がわからないかを整理する

🔍 ヒント（段階的開示）

📋 コピーmkdir day039 && cd day039
go mod init example.com/day039
# main.go に上記コードを保存する
go build -o day039bin .
./day039bin -memprofile=mem.prof
# report length: XXXXXXX が出力され、mem.prof が生成される

go tool pprof -top -alloc_space mem.prof
# 上位に buildReportSlow が alloc_space の大半を占める形で出るはずである

go tool pprof -top -inuse_space mem.prof
# alloc_space と比べて桁違いに小さい値になるはずである

go tool pprof mem.prof
# 対話モードに入ったら以下を試す
# (pprof) list buildReportSlow

✅ 模範解答

1. メモリプロファイル取得の手順

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

# 2. -memprofile フラグを付けて実行し、プロファイルを取得する
go build -o day039bin .
./day039bin -memprofile=mem.prof
# 標準出力: report length: 1450000（値は環境依存）
# カレントディレクトリに mem.prof が生成される

# 3. go tool pprof で累積アロケーション(alloc_space)を確認する
go tool pprof -top -alloc_space mem.prof

# 4. 比較のため、スナップショット時点の生存バイト数(inuse_space、デフォルト)も確認する
go tool pprof -top -inuse_space mem.prof

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

📋 コピーShowing nodes accounting for 950.12MB, 99.80% of 951.98MB total
      flat  flat%   sum%        cum   cum%
  920.45MB 96.70% 96.70%   950.12MB 99.80%  main.buildReportSlow
   29.67MB  3.12% 99.82%    29.67MB  3.12%  strconv.Itoa

-inuse_spaceの出力イメージ:

📋 コピーShowing nodes accounting for 1.45MB, 98.60% of 1.47MB total
      flat  flat%   sum%        cum   cum%
     1.45MB 98.60% 98.60%     1.45MB 98.60%  main.buildReportSlow

2. alloc_spaceの大半を占める関数の予測

buildReportSlowが圧倒的にalloc_spaceの大半（95%超）を占めると予測できます。理由は次の通りです。

• ループ内のreport += "line " + strconv.Itoa(i) + ": some log data here\n"は、実行のたびに新しい文字列（新しいバイト列）をヒープに確保する。式の評価順序としても、右辺の文字列連結自体が中間文字列を生成し、さらにその結果をreportに代入する際に古いreportの中身をコピーした新しいバイト列が確保される
• strconv.Itoa(i)も毎回小さなアロケーションを行うが、report本体の再構築で発生するバイト数（ループが進むごとに線形に増大していく）に比べればごくわずかである
• buildReportSlowは子関数を呼び出してはいるものの、支配的なコストは自分自身の代入・連結処理そのものにあるため、flatが極めて高くなる

3. alloc_spaceとinuse_spaceが大きく乖離する理由

Goの文字列は不変です。report += ...は「既存のreportを書き換える」のではなく、「新しいバイト列を確保し、reportという変数がそちらを指すように付け替える」という操作です。この結果、i回目のループでは、それまでのreportの長さにほぼ比例したバイト数の新しい確保が発生します。n回のループ全体を通した確保バイト数の合計は、およそ以下のように見積もれます。

📋 コピー確保バイト数の合計 ≈ Σ(i=1 to n) (1行あたりの長さ × i) ∝ n²

つまりalloc_spaceはnの2乗のオーダーで積み上がっていきます。一方で、i回目に確保された「古い方の」バイト列は、i+1回目の代入が終わった瞬間にどこからも参照されなくなり、ガベージコレクションの対象になります。プログラムの最後でruntime.GC()を呼んでからスナップショットを取ると、そうした使い捨ての中間文字列はすでに回収済みで、inuse_spaceには最終的なreport一つ分の実サイズしか残りません。

4. strings.Builderによる書き直し

📋 コピーpackage main

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

// buildReportFast は strings.Builder を使い、n行分の行を結合してレポートを生成する。
// buildReportSlow(文字列連結によるO(n²)アロケーション)と異なり、
// バッファへの追記のみでレポートを構築する。
func buildReportFast(n int) string {
	var b strings.Builder
	b.Grow(n * 32) // 1行あたりのおおよそのサイズで事前に容量を確保し、再確保を避ける
	for i := 0; i < n; i++ {
		b.WriteString("line ")
		b.WriteString(strconv.Itoa(i))
		b.WriteString(": some log data here\n")
	}
	return b.String()
}

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

	report := buildReportFast(50000)
	fmt.Println("report length:", len(report))

	if *memprofile != "" {
		f, err := os.Create(*memprofile)
		if err != nil {
			fmt.Fprintln(os.Stderr, "could not create memory profile:", err)
			os.Exit(1)
		}
		defer f.Close()
		runtime.GC()
		if err := pprof.WriteHeapProfile(f); err != nil {
			fmt.Fprintln(os.Stderr, "could not write memory profile:", err)
			os.Exit(1)
		}
	}
}

buildReportSlow(50000)とbuildReportFast(50000)は同じ内容・同じ長さの文字列を返します（外部から見た戻り値は不変）。Grow(n * 32)によって、バッファの拡張（内部スライスの再確保とコピー）はほぼ発生しなくなり、WriteStringは既存バッファへの追記だけで済みます。

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

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

修正前はbuildReportSlowのalloc_spaceがn²オーダーで巨大でしたが、修正後はbuildReportFastのalloc_spaceが最終的な文字列サイズとほぼ同じオーダー（Growにより1〜数回の内部バッファ確保のみ）まで劇的に減少します。alloc_spaceとinuse_spaceの乖離もほぼ解消され、両者が近い値になるはずです。これは「ゴミを大量に作ってGCに掃除させる」パターンから「必要な分だけ確保する」パターンへ変わったことの直接的な証拠になります。

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

📋 コピー// main_test.go
package main

import "testing"

func BenchmarkBuildReportFast(b *testing.B) {
	for i := 0; i < b.N; i++ {
		buildReportFast(50000)
	}
}

func BenchmarkBuildReportSlow(b *testing.B) {
	for i := 0; i < b.N; i++ {
		buildReportSlow(50000)
	}
}

📋 コピーgo test -bench . -benchmem -memprofile=mem.prof -benchtime=5x
go tool pprof -top -alloc_space mem.prof

-benchmemはベンチマーク結果のサマリ（1回あたりのアロケーション回数・バイト数）をテキストで即座に表示してくれる一方、-memprofileはさらに詳細な「どの行が」アロケーションしているかまでgo tool pprofで掘り下げられる形で保存します。両者は併用が前提であり、まず-benchmemの数字で「悪化していないか」を確認し、悪化していれば-memprofileで原因箇所を特定する、という順序で使います。

6. 静的なエスケープ解析予測と動的なメモリプロファイリングの違い

🪜 Step-by-Step 解説

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

🌐 他言語との比較

🏆 実務での使いどころ

• バッチ処理・レポート生成のパフォーマンス劣化調査: 大量データを文字列やスライスに逐次追記していく処理は、データ量が増えるにつれて指数関数的にではなく二次関数的に遅くなることが多い。ユーザー数・データ件数の増加でバッチが急に遅くなったときの典型的な原因の一つ
• GC負荷が高いサービスの調査: レイテンシのp99が不安定なサービスで、CPU使用率は低いのにGCの実行頻度が高い場合、-alloc_spaceを見て「無駄に大量のゴミを作っている箇所」を特定する
• メモリリークとアロケーション過多の切り分け: 「メモリ使用量が増え続けている」という報告に対して、inuse_spaceを時系列で複数回取得し増加傾向があればリーク、alloc_spaceだけが大きくinuse_spaceは安定していればアロケーション過多（churn）、と原因を切り分けられる
• 文字列・スライス構築処理のコードレビュー基準: ループ内で+=（文字列）や、容量指定なしのappend（スライス）を見つけたら、strings.Builderやmake([]T, 0, cap)への置き換えを検討する、という具体的なレビュー観点として使える

⚠️ よくある誤解・ミス

🚀 次のステップ

• 発展: go tool pprof -http=:8080 -alloc_space mem.profを実行し、ブラウザ上でFlame Graphを確認してみましょう。buildReportSlowの呼び出し1回1回がどのように積み上がっているかを、テキストのtopよりも直感的に把握できます
• 次回予告: ベンチマーク駆動最適化 — Day 040では、Day 038（CPU）・Day 039（メモリ）で学んだ2種類のプロファイリングを組み合わせ、Before/Afterの数値を定量的に比較しながら最適化を進める一連のワークフローを扱います

🎯 自己評価

自分の回答

気づき・メモ