よっしー
こんにちは。よっしーです(^^)
本日は、Go言語のパフォーマンス分析ついて解説しています。
スポンサーリンク
背景
Go言語でアプリケーションを開発していると、必ずと言っていいほど直面するのがパフォーマンスの問題や予期しないバグです。「なぜこんなにメモリを消費しているのか？」「どこで処理が遅くなっているのか？」「このゴルーチンはなぜデッドロックしているのか？」—— こうした疑問に答えるために、Goのエコシステムには強力な診断ツール群が用意されています。
しかし、これらのツールは種類が多く、それぞれ異なる目的と特性を持っているため、どのような場面でどのツールを使うべきか迷ってしまうことも少なくありません。プロファイリング、トレーシング、デバッギング、ランタイム統計…それぞれのツールが解決できる問題は異なり、時には相互に干渉し合うこともあります。
本記事では、Go公式ドキュメントの診断ツールに関する解説を日本語で紹介しながら、実際の開発現場でどのように活用できるかを探っていきます。適切なツールを選択し、効果的に問題を診断することで、より高品質で高性能なGoアプリケーションの開発が可能になるはずです。特に、パフォーマンスのボトルネックを特定し改善することは、ユーザー体験の向上やインフラコストの削減に直結する重要なスキルと言えるでしょう。
トレースに含めることができる標準ライブラリやランタイムの他の低レベルイベントは何ですか？
標準ライブラリとランタイムは、低レベルの内部イベントを通知するための追加APIを公開しようとしています。例えば、httptrace.ClientTraceは、送信リクエストのライフサイクルにおける低レベルイベントを追跡するAPIを提供します。ランタイム実行トレーサーから低レベルのランタイムイベントを取得し、ユーザーが独自のイベントを定義して記録できるようにする取り組みが進行中です。
低レベルイベント – プログラムの「心電図」
低レベルイベントとは？
例え: 車のエンジン内部のピストンの動きや燃料噴射のタイミングを見るようなもの
通常見えないプログラムの内部動作を詳細に観察できます。
httptrace.ClientTrace – HTTPリクエストの解剖
利用可能なイベント一覧
package main
import (
"context"
"crypto/tls"
"fmt"
"net/http"
"net/http/httptrace"
"time"
)
func traceHTTPRequest() {
// 各段階の時間を記録
var (
dnsStart time.Time
dnsDone time.Time
connectDone time.Time
gotConn time.Time
firstByte time.Time
)
// ClientTraceで全てのイベントをフック
trace := &httptrace.ClientTrace{
// DNS解決開始
DNSStart: func(info httptrace.DNSStartInfo) {
dnsStart = time.Now()
fmt.Printf("DNS lookup starting for %s\n", info.Host)
},
// DNS解決完了
DNSDone: func(info httptrace.DNSDoneInfo) {
dnsDone = time.Now()
fmt.Printf("DNS lookup done in %v\n", dnsDone.Sub(dnsStart))
if info.Err != nil {
fmt.Printf("DNS error: %v\n", info.Err)
} else {
fmt.Printf("DNS resolved to: %v\n", info.Addrs)
}
},
// TCP接続開始
ConnectStart: func(network, addr string) {
fmt.Printf("Connecting to %s %s\n", network, addr)
},
// TCP接続完了
ConnectDone: func(network, addr string, err error) {
connectDone = time.Now()
if err != nil {
fmt.Printf("Connection failed: %v\n", err)
} else {
fmt.Printf("Connected to %s\n", addr)
}
},
// TLSハンドシェイク開始
TLSHandshakeStart: func() {
fmt.Println("TLS handshake starting...")
},
// TLSハンドシェイク完了
TLSHandshakeDone: func(state tls.ConnectionState, err error) {
if err != nil {
fmt.Printf("TLS handshake failed: %v\n", err)
} else {
fmt.Printf("TLS version: %x, Cipher: %x\n",
state.Version, state.CipherSuite)
}
},
// 接続取得（接続プールから）
GotConn: func(info httptrace.GotConnInfo) {
gotConn = time.Now()
fmt.Printf("Got connection: reused=%v, idle=%v\n",
info.Reused, info.IdleTime)
},
// HTTPヘッダー書き込み
WroteHeaders: func() {
fmt.Println("Request headers sent")
},
// リクエストボディ書き込み
WroteRequest: func(info httptrace.WroteRequestInfo) {
if info.Err != nil {
fmt.Printf("Error writing request: %v\n", info.Err)
} else {
fmt.Println("Request body sent")
}
},
// 最初のレスポンスバイト受信
GotFirstResponseByte: func() {
firstByte = time.Now()
fmt.Printf("First byte received after %v\n",
firstByte.Sub(gotConn))
},
}
// トレースをcontextに追加
ctx := httptrace.WithClientTrace(context.Background(), trace)
// HTTPリクエスト実行
req, _ := http.NewRequestWithContext(ctx, "GET", "https://example.com", nil)
client := &http.Client{
Timeout: 10 * time.Second,
}
resp, err := client.Do(req)
if err != nil {
fmt.Printf("Request failed: %v\n", err)
return
}
defer resp.Body.Close()
fmt.Printf("Response status: %s\n", resp.Status)
}
実践的な活用例：パフォーマンス分析ツール
// HTTPパフォーマンスアナライザー
type HTTPPerformanceAnalyzer struct {
metrics map[string]*RequestMetrics
mu sync.Mutex
}
type RequestMetrics struct {
DNSLookup time.Duration
TCPConnection time.Duration
TLSHandshake time.Duration
ServerProcessing time.Duration
ContentTransfer time.Duration
Total time.Duration
ConnectionReused bool
DNSCoalesced bool
}
func (a *HTTPPerformanceAnalyzer) Trace(req *http.Request) *httptrace.ClientTrace {
metrics := &RequestMetrics{}
reqID := generateRequestID()
var (
start = time.Now()
dnsStart time.Time
connectStart time.Time
tlsStart time.Time
requestSent time.Time
firstByteTime time.Time
)
return &httptrace.ClientTrace{
DNSStart: func(_ httptrace.DNSStartInfo) {
dnsStart = time.Now()
},
DNSDone: func(info httptrace.DNSDoneInfo) {
if !dnsStart.IsZero() {
metrics.DNSLookup = time.Since(dnsStart)
}
metrics.DNSCoalesced = info.Coalesced
},
ConnectStart: func(_, _ string) {
connectStart = time.Now()
},
ConnectDone: func(_, _ string, err error) {
if !connectStart.IsZero() && err == nil {
metrics.TCPConnection = time.Since(connectStart)
}
},
TLSHandshakeStart: func() {
tlsStart = time.Now()
},
TLSHandshakeDone: func(_ tls.ConnectionState, err error) {
if !tlsStart.IsZero() && err == nil {
metrics.TLSHandshake = time.Since(tlsStart)
}
},
GotConn: func(info httptrace.GotConnInfo) {
metrics.ConnectionReused = info.Reused
},
WroteRequest: func(_ httptrace.WroteRequestInfo) {
requestSent = time.Now()
},
GotFirstResponseByte: func() {
firstByteTime = time.Now()
if !requestSent.IsZero() {
metrics.ServerProcessing = firstByteTime.Sub(requestSent)
}
},
Done: func() {
metrics.Total = time.Since(start)
if !firstByteTime.IsZero() {
metrics.ContentTransfer = time.Since(firstByteTime)
}
// メトリクスを保存
a.mu.Lock()
a.metrics[reqID] = metrics
a.mu.Unlock()
// 分析結果を出力
a.printAnalysis(reqID, metrics)
},
}
}
func (a *HTTPPerformanceAnalyzer) printAnalysis(reqID string, m *RequestMetrics) {
fmt.Printf("\n=== Request Performance Analysis [%s] ===\n", reqID)
fmt.Printf("DNS Lookup: %10v (%.1f%%)\n",
m.DNSLookup, percent(m.DNSLookup, m.Total))
fmt.Printf("TCP Connection: %10v (%.1f%%)\n",
m.TCPConnection, percent(m.TCPConnection, m.Total))
fmt.Printf("TLS Handshake: %10v (%.1f%%)\n",
m.TLSHandshake, percent(m.TLSHandshake, m.Total))
fmt.Printf("Server Processing: %10v (%.1f%%)\n",
m.ServerProcessing, percent(m.ServerProcessing, m.Total))
fmt.Printf("Content Transfer: %10v (%.1f%%)\n",
m.ContentTransfer, percent(m.ContentTransfer, m.Total))
fmt.Printf("─────────────────────────────────────────\n")
fmt.Printf("Total: %10v\n", m.Total)
fmt.Printf("\nOptimizations:\n")
if m.ConnectionReused {
fmt.Println("✓ Connection was reused (saved TCP+TLS time)")
}
if m.DNSCoalesced {
fmt.Println("✓ DNS was coalesced with another request")
}
}
ランタイムイベントトレーシング
package main
import (
"fmt"
"os"
"runtime"
"runtime/trace"
"sync"
"time"
)
func traceRuntimeEvents() {
// トレースファイル作成
f, _ := os.Create("runtime.trace")
defer f.Close()
// トレース開始
trace.Start(f)
defer trace.Stop()
// カスタムタスク
ctx, task := trace.NewTask(context.Background(), "myTask")
defer task.End()
// リージョンでコードブロックをマーク
trace.WithRegion(ctx, "dataProcessing", func() {
processData()
})
// ユーザー定義イベント
trace.Log(ctx, "checkpoint", "Starting heavy computation")
// ゴルーチンの作成と同期
var wg sync.WaitGroup
for i := 0; i < 10; i++ {
wg.Add(1)
go func(id int) {
defer wg.Done()
// 各ゴルーチンでリージョンを定義
trace.WithRegion(ctx, fmt.Sprintf("worker-%d", id), func() {
time.Sleep(time.Duration(id) * 10 * time.Millisecond)
})
}(i)
}
wg.Wait()
}
// 分析方法：
// go tool trace runtime.trace
// ブラウザで以下が確認できる：
// - ゴルーチンのスケジューリング
// - GCの動作
// - システムコール
// - ユーザー定義イベント
その他の低レベルトレーシング機能
1. runtime/metrics – ランタイムメトリクス
import (
"runtime/metrics"
)
func collectRuntimeMetrics() {
// 利用可能なメトリクス一覧
descs := metrics.All()
// 収集したいメトリクスを選択
samples := []metrics.Sample{
{Name: "/memory/classes/heap/objects:bytes"},
{Name: "/memory/classes/heap/unused:bytes"},
{Name: "/gc/cycles/automatic:gc-cycles"},
{Name: "/gc/heap/allocs:bytes"},
{Name: "/gc/heap/goal:bytes"},
{Name: "/sched/goroutines:goroutines"},
}
// メトリクス読み取り
metrics.Read(samples)
for _, sample := range samples {
fmt.Printf("%s: ", sample.Name)
switch value := sample.Value.(type) {
case metrics.Value:
fmt.Printf("%v\n", value)
case uint64:
fmt.Printf("%d\n", value)
case float64:
fmt.Printf("%.2f\n", value)
}
}
}
2. runtime.ReadMemStats – メモリ統計
func traceMemoryStats() {
var m runtime.MemStats
ticker := time.NewTicker(1 * time.Second)
defer ticker.Stop()
for range ticker.C {
runtime.ReadMemStats(&m)
fmt.Printf("Memory Stats:\n")
fmt.Printf(" Alloc: %d MB\n", m.Alloc/1024/1024)
fmt.Printf(" TotalAlloc: %d MB\n", m.TotalAlloc/1024/1024)
fmt.Printf(" Sys: %d MB\n", m.Sys/1024/1024)
fmt.Printf(" NumGC: %d\n", m.NumGC)
fmt.Printf(" Goroutines: %d\n", runtime.NumGoroutine())
}
}
3. debug.Stack – スタックトレース
import (
"runtime/debug"
)
func captureStackTrace() {
// パニック時の自動スタックトレース
defer func() {
if r := recover(); r != nil {
stackTrace := debug.Stack()
fmt.Printf("Panic: %v\n", r)
fmt.Printf("Stack trace:\n%s\n", stackTrace)
}
}()
// 任意の時点でスタックトレース取得
fmt.Printf("Current stack:\n%s\n", debug.Stack())
}
統合例：包括的なトレーシングシステム
type ComprehensiveTracer struct {
httpTrace *HTTPPerformanceAnalyzer
runtimeTrace *os.File
metrics chan MetricEvent
}
type MetricEvent struct {
Timestamp time.Time
Type string
Value interface{}
}
func (ct *ComprehensiveTracer) TraceRequest(req *http.Request) *http.Request {
// HTTPトレース追加
trace := ct.httpTrace.Trace(req)
ctx := httptrace.WithClientTrace(req.Context(), trace)
// ランタイムイベント記録
ctx, task := trace.NewTask(ctx, "http-request")
defer task.End()
// メトリクス収集開始
go ct.collectMetricsDuring(ctx)
return req.WithContext(ctx)
}
func (ct *ComprehensiveTracer) collectMetricsDuring(ctx context.Context) {
ticker := time.NewTicker(10 * time.Millisecond)
defer ticker.Stop()
for {
select {
case <-ctx.Done():
return
case <-ticker.C:
// GC統計
var m runtime.MemStats
runtime.ReadMemStats(&m)
ct.metrics <- MetricEvent{
Timestamp: time.Now(),
Type: "memory",
Value: map[string]uint64{
"alloc": m.Alloc,
"goroutines": uint64(runtime.NumGoroutine()),
},
}
}
}
}
将来の展望
Goチームが取り組んでいる機能：
- ユーザー定義イベント
- カスタムイベントの記録
- ビジネスロジックのトレース
- より詳細なランタイムイベント
- メモリアロケーションの詳細
- ゴルーチンの状態遷移
- チャネル操作
- 統一されたトレーシングAPI
- 全ての低レベルイベントへの統一アクセス
低レベルイベントトレーシングを活用することで、アプリケーションの動作を「顕微鏡レベル」で観察し、最適化の機会を見つけることができます！
おわりに
本日は、Go言語のパフォーマンス分析について解説しました。
よっしー
何か質問や相談があれば、コメントをお願いします。また、エンジニア案件の相談にも随時対応していますので、お気軽にお問い合わせください。
それでは、また明日お会いしましょう(^^)
コメント