よっしー
こんにちは。よっしーです(^^)
本日は、Go言語のパフォーマンス分析ついて解説しています。
スポンサーリンク
背景
Go言語でアプリケーションを開発していると、必ずと言っていいほど直面するのがパフォーマンスの問題や予期しないバグです。「なぜこんなにメモリを消費しているのか？」「どこで処理が遅くなっているのか？」「このゴルーチンはなぜデッドロックしているのか？」—— こうした疑問に答えるために、Goのエコシステムには強力な診断ツール群が用意されています。
しかし、これらのツールは種類が多く、それぞれ異なる目的と特性を持っているため、どのような場面でどのツールを使うべきか迷ってしまうことも少なくありません。プロファイリング、トレーシング、デバッギング、ランタイム統計…それぞれのツールが解決できる問題は異なり、時には相互に干渉し合うこともあります。
本記事では、Go公式ドキュメントの診断ツールに関する解説を日本語で紹介しながら、実際の開発現場でどのように活用できるかを探っていきます。適切なツールを選択し、効果的に問題を診断することで、より高品質で高性能なGoアプリケーションの開発が可能になるはずです。特に、パフォーマンスのボトルネックを特定し改善することは、ユーザー体験の向上やインフラコストの削減に直結する重要なスキルと言えるでしょう。
GODEBUG
ランタイムは、GODEBUG環境変数が適切に設定されている場合、イベントと情報を出力します。
GODEBUG=gctrace=1は、各コレクションでガベージコレクタイベントを出力し、収集されたメモリ量と一時停止の長さを要約します。GODEBUG=inittrace=1は、完了したパッケージ初期化作業の実行時間とメモリ割り当て情報の概要を出力します。GODEBUG=schedtrace=Xは、Xミリ秒ごとにスケジューリングイベントを出力します。
GODEBUG環境変数は、標準ライブラリとランタイムでの命令セット拡張の使用を無効にするためにも使用できます。
GODEBUG=cpu.all=offは、すべてのオプションの命令セット拡張の使用を無効にします。GODEBUG=cpu.extension=offは、指定された命令セット拡張からの命令の使用を無効にします。extensionは、sse41やavxなどの命令セット拡張の小文字の名前です。
GODEBUG – ランタイムの「診断モード」
GODEBUGとは？
例え: 車の診断モードのように、通常は見えない内部動作を表示する特別なモード
環境変数を設定するだけで、Goプログラムの内部動作を詳細に観察できます。
gctrace – ガベージコレクション診断
基本的な使い方
# GCトレースを有効にして実行
$ GODEBUG=gctrace=1 go run main.go
# または
$ export GODEBUG=gctrace=1
$ ./myapp
出力の読み方
package main
import (
"fmt"
"runtime"
"time"
)
func main() {
// メモリを大量に使用してGCを発生させる
for i := 0; i < 10; i++ {
data := make([]byte, 10*1024*1024) // 10MB
_ = data
time.Sleep(100 * time.Millisecond)
runtime.GC() // 手動でGC実行
}
}
GCトレースの出力例:
gc 1 @0.012s 5%: 0.018+1.3+0.021 ms clock, 0.14+0.35/1.2/0.89+0.17 ms cpu, 4->4->2 MB, 5 MB goal, 8 P
gc 2 @0.025s 7%: 0.008+0.72+0.017 ms clock, 0.070+0.22/0.64/0.45+0.14 ms cpu, 4->4->2 MB, 5 MB goal, 8 P
出力の詳細解説
gc 1 @0.012s 5%: 0.018+1.3+0.021 ms clock, 0.14+0.35/1.2/0.89+0.17 ms cpu, 4->4->2 MB, 5 MB goal, 8 P
│ │ │ │ │ │ │ │ └─ Pの数（プロセッサ）
│ │ │ │ │ │ │ └─ 次回GC目標
│ │ │ │ │ │ └─ GC前→GC中→GC後のヒープサイズ
│ │ │ │ │ └─ CPU時間の詳細
│ │ │ │ └─ 実時間（STW+並行マーク+STW）
│ │ │ └─ GCが使用したCPU割合
│ │ └─ プログラム開始からの時間
│ └─ GC番号
└─ ガベージコレクション
実践的な分析スクリプト
package main
import (
"bufio"
"fmt"
"os"
"regexp"
"strconv"
"strings"
)
// GCトレース解析ツール
type GCAnalyzer struct {
TotalGCs int
TotalPause float64
MaxPause float64
AvgPause float64
HeapSizes []int
}
func analyzeGCTrace(output string) *GCAnalyzer {
analyzer := &GCAnalyzer{}
scanner := bufio.NewScanner(strings.NewReader(output))
// 正規表現でGCトレース行をパース
gcPattern := regexp.MustCompile(`gc (\d+) @([\d.]+)s ([\d.]+)%: ([\d.+]+) ms`)
heapPattern := regexp.MustCompile(`(\d+)->(\d+)->(\d+) MB`)
for scanner.Scan() {
line := scanner.Text()
if gcMatches := gcPattern.FindStringSubmatch(line); gcMatches != nil {
analyzer.TotalGCs++
// 一時停止時間を解析
pauseStr := gcMatches[4]
parts := strings.Split(pauseStr, "+")
totalPause := 0.0
for _, part := range parts {
if val, err := strconv.ParseFloat(part, 64); err == nil {
totalPause += val
}
}
analyzer.TotalPause += totalPause
if totalPause > analyzer.MaxPause {
analyzer.MaxPause = totalPause
}
}
if heapMatches := heapPattern.FindStringSubmatch(line); heapMatches != nil {
if after, err := strconv.Atoi(heapMatches[3]); err == nil {
analyzer.HeapSizes = append(analyzer.HeapSizes, after)
}
}
}
if analyzer.TotalGCs > 0 {
analyzer.AvgPause = analyzer.TotalPause / float64(analyzer.TotalGCs)
}
return analyzer
}
// 使用例
func main() {
// GCトレースを収集（実際は GODEBUG=gctrace=1 で実行）
output := `
gc 1 @0.012s 5%: 0.018+1.3+0.021 ms clock, 4->4->2 MB, 5 MB goal, 8 P
gc 2 @0.025s 7%: 0.008+0.72+0.017 ms clock, 4->4->2 MB, 5 MB goal, 8 P
`
analyzer := analyzeGCTrace(output)
fmt.Printf("GC統計:\n")
fmt.Printf(" 総GC回数: %d\n", analyzer.TotalGCs)
fmt.Printf(" 平均停止時間: %.3f ms\n", analyzer.AvgPause)
fmt.Printf(" 最大停止時間: %.3f ms\n", analyzer.MaxPause)
}
inittrace – パッケージ初期化診断
使い方と解析
# パッケージ初期化のトレース
$ GODEBUG=inittrace=1 go run main.go
package main
import (
_ "database/sql"
_ "encoding/json"
_ "net/http"
"time"
)
var (
// 重い初期化処理
globalData = initializeData()
)
func initializeData() []byte {
time.Sleep(10 * time.Millisecond) // 初期化に時間がかかる
return make([]byte, 1024*1024)
}
func init() {
// init関数での処理
time.Sleep(5 * time.Millisecond)
}
func main() {
// メイン処理
}
出力例:
init database/sql @0.001 ms, 0.021 ms clock, 2048 bytes, 15 allocs
init encoding/json @0.023 ms, 0.015 ms clock, 1024 bytes, 8 allocs
init net/http @0.039 ms, 0.045 ms clock, 4096 bytes, 32 allocs
init main @0.085 ms, 15.234 ms clock, 1048576 bytes, 2 allocs
schedtrace – スケジューラー診断
詳細なスケジューリング情報
# 1秒（1000ms）ごとにスケジューラー情報を出力
$ GODEBUG=schedtrace=1000 ./myapp
package main
import (
"fmt"
"runtime"
"sync"
"time"
)
func main() {
// 複数のゴルーチンを起動してスケジューリングを観察
var wg sync.WaitGroup
for i := 0; i < 100; i++ {
wg.Add(1)
go func(id int) {
defer wg.Done()
// CPU負荷
for j := 0; j < 1000000; j++ {
_ = j * j
}
// I/O待機
time.Sleep(10 * time.Millisecond)
fmt.Printf("Goroutine %d completed\n", id)
}(i)
}
wg.Wait()
}
スケジュールトレース出力:
SCHED 0ms: gomaxprocs=8 idleprocs=6 threads=10 spinningthreads=1 idlethreads=3 runqueue=0 [0 0 0 0 0 0 0 0]
SCHED 1001ms: gomaxprocs=8 idleprocs=2 threads=10 spinningthreads=0 idlethreads=3 runqueue=15 [2 3 1 0 4 2 1 2]
出力の解説:
SCHED 1001ms: gomaxprocs=8 idleprocs=2 threads=10 spinningthreads=0 idlethreads=3 runqueue=15 [2 3 1 0 4 2 1 2]
│ │ │ │ │ │ │ └─ 各Pのローカルキュー
│ │ │ │ │ │ └─ グローバルキュー
│ │ │ │ │ └─ アイドルスレッド
│ │ │ │ └─ スピニング中のスレッド
│ │ │ └─ OSスレッド総数
│ │ └─ アイドルプロセッサ
│ └─ GOMAXPROCS設定値
└─ プログラム開始からの時間
CPU命令セット制御
命令セット拡張の無効化
# すべての拡張命令を無効化（互換性テスト用）
$ GODEBUG=cpu.all=off ./myapp
# 特定の拡張のみ無効化
$ GODEBUG=cpu.avx=off ./myapp # AVX無効化
$ GODEBUG=cpu.sse41=off ./myapp # SSE4.1無効化
$ GODEBUG=cpu.avx2=off ./myapp # AVX2無効化
package main
import (
"fmt"
"runtime"
)
func checkCPUFeatures() {
fmt.Println("=== CPU機能チェック ===")
// アーキテクチャ情報
fmt.Printf("GOARCH: %s\n", runtime.GOARCH)
fmt.Printf("GOMAXPROCS: %d\n", runtime.GOMAXPROCS(0))
fmt.Printf("NumCPU: %d\n", runtime.NumCPU())
// 環境変数チェック
if godebug := os.Getenv("GODEBUG"); godebug != "" {
fmt.Printf("GODEBUG: %s\n", godebug)
}
}
// パフォーマンステスト
func benchmarkWithCPUFeatures() {
// 通常実行
start := time.Now()
performCalculation()
normal := time.Since(start)
fmt.Printf("通常実行: %v\n", normal)
// CPU拡張無効で再実行（別プロセスで）
// GODEBUG=cpu.all=off での実行時間と比較
}
func performCalculation() {
// SIMD命令が使われる可能性のある処理
data := make([]float64, 1000000)
for i := range data {
data[i] = float64(i) * 1.5
}
sum := 0.0
for _, v := range data {
sum += v
}
}
複数のGODEBUGオプションを組み合わせる
# 複数のオプションをカンマで区切る
$ GODEBUG=gctrace=1,schedtrace=1000,inittrace=1 ./myapp
本番環境での活用例
package main
import (
"log"
"os"
"runtime"
"time"
)
// 診断モード管理
type DiagnosticMode struct {
Enabled bool
Options map[string]string
}
func (d *DiagnosticMode) Apply() {
if !d.Enabled {
return
}
debugStr := ""
for key, value := range d.Options {
if debugStr != "" {
debugStr += ","
}
debugStr += key + "=" + value
}
os.Setenv("GODEBUG", debugStr)
log.Printf("診断モード有効: GODEBUG=%s", debugStr)
}
func main() {
// 本番環境での条件付き診断
diagnostic := &DiagnosticMode{
Enabled: os.Getenv("ENABLE_DIAGNOSTICS") == "true",
Options: map[string]string{
"gctrace": "1",
"schedtrace": "10000", // 10秒ごと
},
}
diagnostic.Apply()
// アプリケーション実行
runApplication()
}
// 診断データの自動収集と送信
func collectDiagnostics() {
if os.Getenv("GODEBUG") == "" {
return
}
// 標準エラー出力をキャプチャ
// （GODEBUGの出力は標準エラーに出る）
// 解析してメトリクスサーバーに送信
}
トラブルシューティングガイド
# 問題別GODEBUG設定
troubleshooting:
high_gc_pause:
setting: "GODEBUG=gctrace=1"
look_for: "長い停止時間"
slow_startup:
setting: "GODEBUG=inittrace=1"
look_for: "時間のかかるパッケージ"
goroutine_leak:
setting: "GODEBUG=schedtrace=1000"
look_for: "runqueueの増加"
cpu_compatibility:
setting: "GODEBUG=cpu.all=off"
look_for: "古いCPUでの動作確認"
パフォーマンス影響
| GODEBUG設定 | パフォーマンス影響 | 用途 |
|---|---|---|
| gctrace=1 | 極小 | 本番可 |
| inittrace=1 | 起動時のみ | 本番可 |
| schedtrace=X | 小 | 短期間なら本番可 |
| cpu.all=off | 大 | テストのみ |
GODEBUGは、コードを変更することなくランタイムの詳細な診断情報を得られる強力なツールです。本番環境でも安全に使用できる設定が多く、問題調査の第一歩として非常に有効です！
おわりに
本日は、Go言語のパフォーマンス分析について解説しました。
よっしー
何か質問や相談があれば、コメントをお願いします。また、エンジニア案件の相談にも随時対応していますので、お気軽にお問い合わせください。
それでは、また明日お会いしましょう(^^)
コメント