Go言語入門:ガベージコレクター -Vol.17-

スポンサーリンク
Go言語入門:ガベージコレクター -Vol.17- ノウハウ
Go言語入門:ガベージコレクター -Vol.17-
この記事は約13分で読めます。
よっしー
よっしー

こんにちは。よっしーです(^^)

本日は、Go言語のガベージコレクターついて解説しています。

スポンサーリンク

背景

Goのガベージコレクター(GC)は、多くの開発者にとって「ブラックボックス」のような存在です。メモリ管理を自動で行ってくれる便利な仕組みである一方、アプリケーションのパフォーマンスに大きな影響を与える要因でもあります。「なぜ突然レスポンスが遅くなるのか?」「メモリ使用量が想定より多いのはなぜか?」「GCの停止時間をもっと短くできないか?」—— こうした疑問は、Goで高性能なアプリケーションを開発する上で避けて通れない課題です。

本記事では、Go公式ドキュメントの「ガベージコレクションガイド」を日本語で紹介します。このガイドは、GCの動作原理を理解し、その知見を活用してアプリケーションのリソース使用効率を改善することを目的としています。特筆すべきは、このドキュメントがガベージコレクションの前提知識を一切要求しない点です。Go言語の基本的な知識さえあれば、誰でもGCの仕組みを深く理解できるよう設計されています。

なぜ今、GCの理解が重要なのでしょうか。クラウドネイティブ時代において、リソースの効率的な活用はコスト削減に直結します。また、マイクロサービスアーキテクチャでは、各サービスのレイテンシが全体のユーザー体験に影響するため、GCによる一時停止を最小限に抑えることが求められます。このガイドを通じて、「なんとなく動いている」から「理解して最適化できる」レベルへとステップアップし、より高品質なGoアプリケーションの開発を目指しましょう。

GCトレース

他のすべてが失敗した場合、Go GCは、GC動作に関するはるかに深い洞察を提供するいくつかの異なる特定のトレースを提供します。これらのトレースは常にSTDERRに直接出力され、GCサイクルごとに1行で、すべてのGoプログラムが認識するGODEBUG環境変数を通じて設定されます。これらは主にGo GC自体のデバッグに役立ちます。GCの実装の詳細についてのある程度の知識が必要ですが、それでもGC動作のより良い理解を得るために時折役立つことがあります。

コアのGCトレースは、GODEBUG=gctrace=1を設定することで有効になります。このトレースによって生成される出力は、runtimeパッケージのドキュメントの環境変数セクションに文書化されています。

「ペーサートレース」と呼ばれる補足的なGCトレースは、さらに深い洞察を提供し、GODEBUG=gcpacertrace=1を設定することで有効になります。この出力を解釈するには、GCの「ペーサー」(追加リソースを参照)の理解が必要であり、これはこのガイドの範囲外です。

GCトレース – GCの詳細ログ

GCトレースは、GCの実行をリアルタイムで表示する詳細ログです。

GCトレースとは?

GCが実行されるたびに1行のログを出力

通常のプログラム:
$ go run main.go
(何も表示されない)

GCトレース有効:
$ GODEBUG=gctrace=1 go run main.go
gc 1 @0.005s 0%: 0.018+1.3+0.076 ms clock, ...
gc 2 @0.010s 0%: 0.020+1.5+0.080 ms clock, ...
gc 3 @0.015s 0%: 0.019+1.4+0.075 ms clock, ...
↑ GCが実行されるたびに出力

いつ使うか?

他の方法で解決できない時:
❌ CPUプロファイルでは情報不足
❌ 実行トレースでは見えない
❌ MemStatsでは詳細がわからない

✅ GCトレース:
  - GCの詳細な動作
  - 各フェーズの時間
  - メモリの変化

例え話:

  • CPUプロファイル = 月次レポート
  • 実行トレース = ビデオ録画
  • GCトレース = リアルタイム速報

基本的な使い方

方法1: コマンドラインから

# 実行時に有効化
GODEBUG=gctrace=1 go run main.go

# ビルド済みバイナリでも使える
GODEBUG=gctrace=1 ./myapp

# テストでも使える
GODEBUG=gctrace=1 go test -run TestMyFunc

方法2: プログラムから設定

package main

import (
    "os"
)

func init() {
    // プログラム内で有効化
    os.Setenv("GODEBUG", "gctrace=1")
}

func main() {
    // アプリケーション実行
    runApp()
}

GCトレースの出力を理解する

基本的な出力例

gc 1 @0.005s 0%: 0.018+1.3+0.076 ms clock, 0.15+0.59/1.2/3.0+0.61 ms cpu, 4->4->3 MB, 5 MB goal, 8 P

これは暗号のように見えますが、実は規則的な構造です。

出力の構造を分解

gc 1 @0.005s 0%: 0.018+1.3+0.076 ms clock, ...
↑  ↑ ↑       ↑  ↑
│  │ │       │  └─ タイミング情報
│  │ │       └─ GCのCPU使用率
│  │ └─ プログラム開始からの経過時間
│  └─ GC番号
└─ GCイベント

各フィールドの意味

1. GC番号と時刻

gc 1 @0.005s
   ↑ ↑
   │ └─ プログラム開始から0.005秒後
   └─ 1回目のGC

2. CPU使用率

0%
↑
└─ GCがCPUの0%を使用(まだ始まったばかり)

注意: これは累積のCPU使用率です。

gc 1 @0.005s 0%   ← 0% (初回)
gc 2 @0.010s 2%   ← 2% (累積)
gc 3 @0.015s 5%   ← 5% (累積)

3. クロック時間

0.018+1.3+0.076 ms clock
↑     ↑   ↑
│     │   └─ マークターミネーション(STW)
│     └─ 並行マーク
└─ マーク準備(STW)

視覚化:

[STW]─[並行マーク]─[STW]
0.018ms  1.3ms    0.076ms

STW = Stop The World (全停止)

4. CPU時間

0.15+0.59/1.2/3.0+0.61 ms cpu
↑    ↑    ↑   ↑   ↑
│    │    │   │   └─ マークターミネーションCPU時間
│    │    │   └─ アイドルマークCPU時間
│    │    └─ マークアシストCPU時間
│    └─ バックグラウンドマークCPU時間
└─ マーク準備CPU時間

意味:

バックグラウンドマーク: 0.59ms
- GCワーカーの時間

マークアシスト: 1.2ms
- アプリがGCを手伝った時間

アイドルマーク: 3.0ms
- 暇なCPUでGCした時間

5. メモリサイズ

4->4->3 MB
↑  ↑  ↑
│  │  └─ GC後のライブヒープ
│  └─ GC開始時のヒープ
└─ GC前のヒープ

視覚化:

GC前:    ████ 4MB
GC開始時: ████ 4MB (変わらず)
GC後:    ███  3MB (1MB回収!)

6. ターゲット

5 MB goal
↑
└─ 次のGCのターゲット

意味: ヒープが5MBに達したら次のGCを実行

7. プロセッサ数

8 P
↑
└─ GOMAXPROCS (使用可能なプロセッサ数)

実例で理解する

例1: 正常なGC

gc 1 @0.005s 0%: 0.018+1.3+0.076 ms clock, 0.15+0.59/1.2/3.0+0.61 ms cpu, 4->4->3 MB, 5 MB goal, 8 P

分析:
✅ STW: 0.018ms + 0.076ms = 0.094ms (短い!)
✅ 並行マーク: 1.3ms (妥当)
✅ マークアシスト: 1.2ms (少ない)
✅ ヒープ: 4MB -> 3MB (25%回収)
→ 健全なGC

例2: 問題のあるGC

gc 15 @2.500s 25%: 5.2+150.5+8.3 ms clock, 41.6+25.3/120.4/200.1+66.4 ms cpu, 200->210->180 MB, 220 MB goal, 8 P

分析:
🔴 CPU使用率: 25% (高すぎ!)
🔴 並行マーク: 150.5ms (長すぎ!)
🔴 マークアシスト: 120.4ms (多すぎ!)
🔴 ヒープ削減: 210MB -> 180MB (14%のみ)
→ GCが問題

よくあるパターン

パターン1: 頻繁なGC

$ GODEBUG=gctrace=1 go run main.go
gc 1 @0.001s ...
gc 2 @0.002s ...
gc 3 @0.003s ...
gc 4 @0.004s ...
↑ 1ミリ秒ごとにGC!

原因: メモリを非常に速く割り当てている
対処: 割り当てを減らす、GOGCを上げる

パターン2: 長いSTW

gc 10 @1.000s 5%: 50.0+10.0+40.0 ms clock, ...
                   ↑           ↑
                   └─ 長いSTW!

原因: 大量のGoroutineやオブジェクト
対処: Goroutine数を減らす

パターン3: 多いマークアシスト

gc 20 @2.000s 15%: 0.02+5.0+0.03 ms clock, 0.16+0.5/80.0/100.0+0.24 ms cpu, ...
                                                        ↑
                                                    80msも!

原因: 割り当てが速すぎる
対処: 割り当て速度を下げる

トレースレベル

gctrace=1 (基本)

GODEBUG=gctrace=1 go run main.go

出力: GCごとに1行

gctrace=2 (詳細)

GODEBUG=gctrace=2 go run main.go

出力: 
- GCごとに1行
- 各ワーカーの詳細
- より詳しい内部情報

注意: gctrace=2は非常に詳細で読みにくいです。通常は不要。

出力の保存と分析

ファイルに保存

# 標準エラーをファイルにリダイレクト
GODEBUG=gctrace=1 go run main.go 2> gc.log

# または、両方を保存
GODEBUG=gctrace=1 go run main.go 2>&1 | tee gc.log

分析スクリプト

# GCの回数を数える
grep "^gc" gc.log | wc -l

# 平均STW時間を計算
grep "^gc" gc.log | awk '{print $6}' | awk -F'+' '{print $1+$3}' | awk '{s+=$1}END{print s/NR}'

# ヒープサイズの推移を見る
grep "^gc" gc.log | awk '{print $12}'

ペーサートレース (上級者向け)

# ペーサートレースを有効化
GODEBUG=gcpacertrace=1 go run main.go

出力例:

pacer: sweep done at heap size 8MB; allocated 2MB during sweep; goal was 10MB
pacer: H_m_prev=8388608 h_t=10485760 H_T=10485760 h_a=2097152 H_a=10485760 h_g=10485760 H_g=10485760 u_a=0.250000 u_g=0.250000 W_a=2097152 W_g=2097152 p_a=0.000000

警告: これは非常に専門的です。

理解に必要な知識:
- GCペーサーアルゴリズム
- ヒープ成長制御
- 割り当て速度予測

通常のアプリケーション開発では不要!

実践的な使い方

使用例1: 本番環境の問題調査

# 本番環境で一時的に有効化
export GODEBUG=gctrace=1
systemctl restart myapp

# ログを確認
journalctl -u myapp | grep "^gc"

# 問題を確認したら無効化
unset GODEBUG
systemctl restart myapp

使用例2: ベンチマーク比較

# 最適化前
GODEBUG=gctrace=1 go test -bench=. 2> before_gc.log

# 最適化後
GODEBUG=gctrace=1 go test -bench=. 2> after_gc.log

# 比較
diff before_gc.log after_gc.log

使用例3: 負荷テスト中の監視

# 負荷テストツールと並行実行
GODEBUG=gctrace=1 ./myapp 2> gc.log &
APP_PID=$!

# 負荷をかける
wrk -t 12 -c 400 -d 30s http://localhost:8080

# 結果を分析
kill $APP_PID
cat gc.log

GCトレースの注意点

注意1: パフォーマンスへの影響

gctrace=1: 
- 影響: 小
- 本番環境でも使用可能

gctrace=2:
- 影響: 中
- 開発/テスト環境で使用

注意2: ログの量

頻繁なGC:
- 1秒に100回GC
- 1時間で36万行のログ!

対処:
- 短時間だけ有効化
- ログローテーション設定

注意3: 解釈の難しさ

gctrace=1:
- 基本的な情報
- ある程度解釈可能

gcpacertrace=1:
- 内部実装の詳細
- 専門知識が必要

よくある質問

Q1: gctrace=1で十分?

A: ほとんどの場合、十分です。

gctrace=1で確認できること:
✅ GC頻度
✅ STW時間
✅ メモリ使用量
✅ 基本的な問題

gctrace=2が必要なケース:
- GC自体のデバッグ
- 非常に複雑な問題
- ワーカーごとの詳細が必要

Q2: 本番環境で使える?

A: 短時間なら大丈夫です。

推奨:
✅ 問題調査時に一時的に有効化
✅ 数分〜数時間程度
✅ ログサイズに注意

非推奨:
❌ 常時有効化
❌ 長期間の有効化

Q3: 他のツールとの併用は?

A: 可能です。

組み合わせ例:
GODEBUG=gctrace=1 go tool pprof ...
GODEBUG=gctrace=1 go tool trace ...

効果:
- 複数の視点からの分析
- より詳細な理解

まとめ表

機能設定用途難易度
基本トレースgctrace=1通常の診断⭐⭐
詳細トレースgctrace=2深い診断⭐⭐⭐⭐
ペーサートレースgcpacertrace=1GC開発⭐⭐⭐⭐⭐

チェックリスト

□ 他の方法を試した
□ GODEBUGを設定
□ 出力をファイルに保存
□ GC頻度を確認
□ STW時間を確認
□ メモリ変化を確認
□ 問題パターンを特定
□ 最適化案を考える
□ 改善後に再測定

最重要ポイント:

gctrace=1は強力だが、 解釈には経験が必要。 まずは基本的なパターンを覚えよう!

推奨される学習順序:

  1. runtime.MemStatsで基本を学ぶ
  2. CPUプロファイルで全体を把握
  3. 実行トレースで詳細を確認
  4. GCトレースで微調整 ← 最後

この順序で進めることで、効率的にGCを理解できます! 📊

おわりに 

本日は、Go言語のガベージコレクターについて解説しました。

よっしー
よっしー

何か質問や相談があれば、コメントをお願いします。また、エンジニア案件の相談にも随時対応していますので、お気軽にお問い合わせください。

それでは、また明日お会いしましょう(^^)

コメント

タイトルとURLをコピーしました