Skip to content

Instantly share code, notes, and snippets.

@podhmo
Created September 19, 2025 18:33
Show Gist options
  • Save podhmo/5b7644c33554701ec107b2efe1d489ea to your computer and use it in GitHub Desktop.
Save podhmo/5b7644c33554701ec107b2efe1d489ea to your computer and use it in GitHub Desktop.

CPU プロファイル解析レポート

概要

  • 実行ファイル: find-orphans
  • プロファイル時間: 2025-09-20 03:17:20 JST
  • 実行時間: 19.76秒
  • 総サンプル時間: 50.16秒 (253.88% - 複数コアを使用)

主要なボトルネック

1. ガベージコレクション (約70%のCPU時間)

プロファイル結果から、CPU時間の約70%がガベージコレクション関連の処理に費やされていることが判明しました。

GC関連の主要関数と使用率:

  • runtime.scanobject: 58.19% (累計)
  • runtime.gcDrain: 62.80% (累計)
  • runtime.gcBgMarkWorker: 61.30% (累計)
  • runtime.findObject: 16.49%
  • runtime.(*mspan).heapBitsSmallForAddr: 16.69%
  • runtime.greyobject: 10.98%

これらの数値は、プログラムが過度のメモリアロケーションを行っており、GCが頻繁に実行されていることを示しています。

2. メモリアロケーション (約12%のCPU時間)

  • runtime.mallocgc: 12.20% (累計)
  • runtime.mallocgcSmallScanNoHeader: 9.15% (累計)
  • runtime.memclrNoHeapPointers: 5.40%
  • runtime.memmove: 2.73%

頻繁な小規模オブジェクトのアロケーションが発生しています。

3. アプリケーション固有のコード (約30%のCPU時間)

  • github.com/podhmo/go-scan/symgo/evaluator.(*Evaluator).Eval: 29.33% (累計)
    • applyFunction: 29.33%
    • evalBlockStatement: 29.33%

評価器の実行が全体の約30%を占めていますが、これ自体は正常です。問題はGCの割合が異常に高いことです。

パフォーマンス改善の推奨事項

1. メモリアロケーションの削減

  • オブジェクトプールの導入: 頻繁に作成・破棄されるオブジェクトに sync.Pool を使用
  • 事前アロケーション: スライスやマップのキャパシティを適切に事前設定
  • 値型の使用: 可能な場合はポインタではなく値型を使用

2. 文字列操作の最適化

  • runtime.concatstrings (2.03%) と runtime.convTstring (3.25%) が頻繁に呼ばれています
  • strings.Builder を使用して文字列連結を効率化
  • 不要な文字列変換を避ける

3. マップ操作の最適化

  • runtime.mapaccess2_faststr (1.44%) と runtime.mapassign_faststr (1.99%) が頻繁
  • マップのサイズを事前に設定
  • 頻繁にアクセスするデータはキャッシュを検討

4. GCチューニング

# GCの頻度を下げる(メモリ使用量は増加)
GOGC=200 ./find-orphans

# 初期ヒープサイズを増やす
GOMEMLIMIT=2GiB ./find-orphans

5. 評価器の最適化候補

  • (*Evaluator).Eval 関数での過度なオブジェクト生成を確認
  • メモ化の改善(既に一部導入されているようですが、さらなる最適化の余地あり)
  • 再帰呼び出しの削減

次のステップ

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

    MEMPROFILE=/tmp/mem.prof ./find-orphans --mode lib --workspace-root . ./symgo/evaluator
    go tool pprof -alloc_space /tmp/mem.prof
  2. アロケーションの詳細分析: 評価器のコードを確認し、以下を特定:

    • 頻繁に作成される一時オブジェクト
    • 不要なコピー操作
    • 最適化可能な文字列操作
  3. ベンチマークテストの作成: 最適化の効果を測定するためのベンチマークを作成

まとめ

現在のプログラムはGCに大部分のCPU時間を費やしており、メモリアロケーションの最適化が最優先課題です。評価器自体のロジックは全体の30%程度しか占めていないため、メモリ管理を改善することで大幅なパフォーマンス向上(2-3倍)が期待できます。

メモリアロケーション削減実施計画

1. 現状の分析結果

プロファイル分析から判明した問題

  • GCが全CPU時間の約70%を消費(通常は5-20%が適正範囲)
  • 頻繁な小規模オブジェクトのアロケーション
  • runtime.mallocgcruntime.mallocgcSmallScanNoHeaderが高頻度で呼ばれる
  • 文字列操作(concatstringsconvTstring)による過度のアロケーション

evaluator.Evalのコード分析から判明したホットスポット

  1. デバッグログでの文字列生成 (evaluator.go:259-275)

    • 毎回bytes.Bufferを作成
    • printer.Fprintによる文字列化
    • ログレベルに関わらず文字列生成が発生する可能性
  2. 大きなswitch文 (evaluator.go:277-405)

    • 各ケースで新規オブジェクト生成
  3. エラーオブジェクトの生成

    • 頻繁なnewError呼び出しによるフォーマット文字列生成

2. 実施計画

フェーズ1: 測定環境の構築(1-2時間)

1.1 ベンチマークテストの作成

// benchmark_test.go
func BenchmarkEvaluator(b *testing.B) {
    // 典型的なワークロードを実行
    // メモリアロケーション数を測定
}

1.2 メモリプロファイルの詳細取得

# アロケーションプロファイル
go test -bench=. -memprofile=mem.prof
go tool pprof -alloc_space mem.prof

# ヒーププロファイル
go test -bench=. -memprofile=heap.prof
go tool pprof -inuse_space heap.prof

フェーズ2: Quick Wins(2-4時間)

2.1 デバッグログの最適化

問題: ログレベルチェック後も文字列生成が発生

// 現在のコード(毎回Bufferを作成)
if e.logger.Enabled(ctx, slog.LevelDebug) {
    var buf bytes.Buffer  // 毎回アロケーション
    printer.Fprint(&buf, fset, node)
}

改善案:

// Buffer poolの導入
var bufferPool = sync.Pool{
    New: func() interface{} {
        return new(bytes.Buffer)
    },
}

if e.logger.Enabled(ctx, slog.LevelDebug) {
    buf := bufferPool.Get().(*bytes.Buffer)
    buf.Reset()
    defer bufferPool.Put(buf)
    printer.Fprint(buf, fset, node)
}

2.2 文字列連結の最適化

問題: 頻繁なfmt.Sprintfや文字列連結

// 現在のコード
return fmt.Sprintf("package.%s.%s", pkg.Name, ident.Name)

改善案:

// strings.Builderを使用
var sb strings.Builder
sb.WriteString("package.")
sb.WriteString(pkg.Name)
sb.WriteByte('.')
sb.WriteString(ident.Name)
return sb.String()

フェーズ3: 構造体の最適化(4-8時間)

3.1 頻繁に作成されるオブジェクトのプール化

// Object poolの導入
type ObjectPool struct {
    variablePool    sync.Pool
    placeholderPool sync.Pool
    errorPool       sync.Pool
}

func (p *ObjectPool) GetVariable() *object.Variable {
    v := p.variablePool.Get()
    if v == nil {
        return &object.Variable{}
    }
    return v.(*object.Variable)
}

func (p *ObjectPool) PutVariable(v *object.Variable) {
    // Reset fields
    v.Name = ""
    v.Value = nil
    p.variablePool.Put(v)
}

3.2 小さな構造体の値渡しへの変更

現在: すべてのobjectがポインタで扱われる 改善: 小さな構造体(16バイト以下)は値型で扱う

フェーズ4: マップとスライスの最適化(4-8時間)

4.1 マップの事前サイズ指定

// 現在のコード
m := make(map[string]object.Object)

// 改善後(サイズが予測可能な場合)
m := make(map[string]object.Object, expectedSize)

4.2 スライスの容量事前確保

// 現在のコード
var results []object.Object
for _, item := range items {
    results = append(results, process(item))  // 複数回の再アロケーション
}

// 改善後
results := make([]object.Object, 0, len(items))
for _, item := range items {
    results = append(results, process(item))
}

フェーズ5: キャッシングとメモ化の強化(8-16時間)

5.1 関数評価結果のキャッシュ強化

type MemoizationCache struct {
    mu    sync.RWMutex
    cache map[memoKey]memoValue
}

type memoKey struct {
    fnPtr  uintptr
    argsHash uint64
}

type memoValue struct {
    result object.Object
    hits   int
}

5.2 型情報のキャッシュ

// 型解決結果をキャッシュ
typeCache := make(map[ast.Expr]*goscan.TypeInfo)

フェーズ6: GCチューニング(2-4時間)

6.1 実行時パラメータの調整

# GC頻度を下げる
GOGC=200 ./find-orphans

# メモリ制限を設定
GOMEMLIMIT=2GiB ./find-orphans

# 両方を組み合わせる
GOGC=200 GOMEMLIMIT=2GiB ./find-orphans

6.2 プロファイルガイドによる最適化(PGO)

# プロファイルを収集
go build -o find-orphans
./find-orphans -cpuprofile=default.pgo

# PGOを使用してビルド
go build -pgo=default.pgo -o find-orphans-optimized

3. 実施順序と期待効果

フェーズ 実装時間 期待される改善 リスク
1. 測定環境構築 1-2時間 - なし
2. Quick Wins 2-4時間 10-20%
3. 構造体最適化 4-8時間 20-30%
4. マップ/スライス 4-8時間 10-15%
5. キャッシング 8-16時間 30-40%
6. GCチューニング 2-4時間 10-20%

総合的な期待効果: 2-3倍の高速化

4. 検証方法

4.1 パフォーマンステスト

# 最適化前
time ./find-orphans --mode lib --workspace-root . ./symgo/evaluator

# 最適化後
time ./find-orphans-optimized --mode lib --workspace-root . ./symgo/evaluator

4.2 メモリ使用量の測定

# メモリ統計を有効にして実行
GODEBUG=gctrace=1 ./find-orphans 2>&1 | grep gc

4.3 アロケーション数の比較

func TestAllocations(t *testing.T) {
    allocs := testing.AllocsPerRun(100, func() {
        // テストケースを実行
    })
    t.Logf("Allocations per run: %.0f", allocs)
}

5. 注意事項

5.1 互換性の維持

  • APIの変更は最小限に
  • 既存のテストがすべてパスすることを確認

5.2 並行性への配慮

  • sync.Poolは並行安全だが、オブジェクトの状態管理に注意
  • キャッシュのrace conditionを避ける

5.3 メモリリークの防止

  • Poolに返却する前にオブジェクトをリセット
  • 循環参照を避ける

6. 成功指標

  • GCのCPU使用率を70%から20%以下に削減
  • 実行時間を50%以上短縮
  • メモリ使用量のピークを30%削減
  • アロケーション数を60%削減

7. ロールバック計画

各フェーズごとにgitでタグ付けし、問題が発生した場合は前のバージョンに戻せるようにする。

git tag -a v1.0-before-optimization
git tag -a v1.1-after-phase2
git tag -a v1.2-after-phase3
# など
@podhmo
Copy link
Author

podhmo commented Sep 19, 2025

結局メモ化がうまく動いていないというだけの話だった

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment