Go Flight Recorderの使い方—MaxBytesが効かない条件と対処

Go の実行トレースを本番で流しっぱなしにできない理由は、単純にデータ量です。7.4秒の負荷をかけただけで 1.96 MiB。同じ負荷を Flight Recorder で拾うと 84 KiB に収まりました。

Go 1.25 で runtime/trace に入った FlightRecorder は、直近数秒のトレースをメモリ上のリングバッファに保持し、問題を検知した瞬間だけファイルに吐き出す仕組みです。以下、go1.26.4 darwin/arm64 (Apple M5 Pro, 18コア) での実測を並べます。

常時トレースは1.96 MiB、スナップショットは84 KiB

実行トレースを本番で流しっぱなしにできない理由

公式ブログ Flight Recorder in Go 1.25 の “Execution traces” セクションは、実行トレースの弱点をこう整理しています。短命なプログラムなら全期間を取れるが、長時間動くサーバーでは出力量が現実的でない。しかも障害は「起きた後」にしか気づけないので、問題発生時にトレースを開始しても手遅れになる。

Flight Recorder が変えるのは、記録する量ではなく保存する量です。ランタイムはこれまで通りイベントを吐き続け、その直近ぶんだけをメモリに置き続けます。

同じ負荷で取り比べる

HTTPサーバーに3000リクエスト・20並列をかけ、trace.Start による全期間トレースと Flight Recorder のスナップショットを同一プロセスで同時に取りました。両者は併用できます。

取得方法	ファイルサイズ	対象期間
trace.Start (全期間)	2,059,490 bytes (1.96 MiB)	7.4秒すべて
FlightRecorder.WriteTo	85,565 bytes (84 KiB)	直近1秒ぶん

差は 24.1倍。スナップショットは全体の 4.2% です。7.4秒でこの比率なので、数時間動くプロセスなら差はさらに開きます。

遅いリクエストを検知してスナップショットを取る

実装は「起動時に Start、閾値を超えたら WriteTo」の2箇所だけです。

package main

import (
	"log"
	"net/http"
	"os"
	"runtime/trace"
	"sync"
	"time"
)

var fr *trace.FlightRecorder

// 遅いリクエストを検知したらスナップショットを1回だけ書き出す
func latencyGuard(next http.Handler, threshold time.Duration) http.Handler {
	var once sync.Once
	return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
		start := time.Now()
		next.ServeHTTP(w, r)

		elapsed := time.Since(start)
		if elapsed <= threshold {
			return
		}
		once.Do(func() {
			f, err := os.Create("slow.trace")
			if err != nil {
				log.Println("create:", err)
				return
			}
			defer f.Close()
			n, err := fr.WriteTo(f)
			if err != nil {
				log.Println("WriteTo:", err)
				return
			}
			log.Printf("snapshot: path=%s latency=%v bytes=%d",
				r.URL.Path, elapsed.Round(time.Millisecond), n)
		})
	})
}

func main() {
	fr = trace.NewFlightRecorder(trace.FlightRecorderConfig{
		MinAge:   1 * time.Second,
		MaxBytes: 1 << 20, // 1 MiB
	})
	if err := fr.Start(); err != nil {
		log.Fatal(err)
	}
	defer fr.Stop()
	log.Printf("flight recorder started: enabled=%v", fr.Enabled())

	mux := http.NewServeMux()
	mux.HandleFunc("GET /work", handler)
	srv := &http.Server{
		Addr:    "127.0.0.1:8099",
		Handler: latencyGuard(mux, 100*time.Millisecond),
	}
	log.Fatal(srv.ListenAndServe())
}

負荷対象のハンドラには、50回に1回だけロックを握ったまま止まるバグを仕込んであります。

var (
	mu    sync.Mutex
	calls int
)

func handler(w http.ResponseWriter, r *http.Request) {
	mu.Lock()
	defer mu.Unlock()
	calls++
	if calls%50 == 0 {
		time.Sleep(120 * time.Millisecond) // ロックを握ったまま止まる
	}
	w.Write([]byte("ok\n"))
}

NewFlightRecorder に渡す2つの設定

FlightRecorderConfig のフィールドは MinAge と MaxBytes だけ。MinAge はウィンドウに保持したい期間の下限、MaxBytes はウィンドウサイズの上限です。公式ブログの “Flight recording” セクションは MinAge について「捕まえたいイベントの2倍程度」を推奨しています。5秒のタイムアウトを追うなら10秒。

両方 0 のときのデフォルト値は pkg.go.dev 上では “implementation defined” としか書かれていませんが、runtime/trace/flightrecorder.go に直接書いてあります。

func NewFlightRecorder(cfg FlightRecorderConfig) *FlightRecorder {
	fr := new(FlightRecorder)
	if cfg.MaxBytes != 0 {
		fr.targetSize = cfg.MaxBytes
	} else {
		fr.targetSize = 10 << 20 // 10 MiB.
	}

	if cfg.MinAge != 0 {
		fr.targetPeriod = cfg.MinAge
	} else {
		fr.targetPeriod = 10 * time.Second
	}
	return fr
}

無指定なら 10 MiB / 10秒。常駐プロセスに黙って10 MiB 積まれるので、明示指定を前提に考えたほうが読みやすくなります。

動かすと84 KiBのファイルが1つ落ちる

2026/08/10 20:11:41 flight recorder started: enabled=true
2026/08/10 20:11:41 snapshot: path=/work latency=121ms bytes=85565
2026/08/10 20:11:49 load: 3000 requests in 7.446s

121ms かかったリクエストを検知した時点で slow.trace が 85,565 bytes。3000回のうち遅かったのは60回ですが、sync.Once で最初の1回だけに絞っています。閾値を超えるたびに書くと、遅い時間帯にディスクI/Oが増えて症状を悪化させます。

84 KiBのスナップショットから遅延の原因を割り出す

スナップショットは通常のトレースファイルと同じ形式なので、go tool trace がそのまま食べます。ブラウザUIを開かずに済ませたいときは -pprof が速い。

go tool trace -pprof=sync slow.trace > sync.pprof
go tool pprof -top -nodecount=6 sync.pprof

Type: delay
Showing nodes accounting for 2765.96ms, 99.71% of 2773.91ms total
Showing top 6 nodes out of 27
      flat  flat%   sum%        cum   cum%
 2294.36ms 82.71% 82.71%  2294.36ms 82.71%  sync.(*Mutex).Lock
  302.99ms 10.92% 93.63%   302.99ms 10.92%  runtime.chanrecv1
  129.48ms  4.67% 98.30%   129.48ms  4.67%  runtime.selectgo
   39.14ms  1.41% 99.71%    39.14ms  1.41%  runtime.gcMarkDone
         0     0% 99.71%  2282.71ms 82.29%  main.handler
         0     0% 99.71%   112.46ms  4.05%  main.loadTest.func1

go tool trace -pprof=sync でロック待ちを出す

1秒ぶん84 KiB のデータから、main.handler のロック待ちに 2282.71ms (82.29%) が集中していると出ました。-pprof に渡せるのは net / sync / syscall / sched の4種類。レイテンシ調査は sync から入って、外れたら sched に移るのが早いです。

-d=footprint でイベントの内訳を見る

ファイルサイズの内訳は -d=footprint で出ます。MaxBytes をいくつにすべきか決めるときの根拠になります。

$ go tool trace -d=footprint slow.trace
Event                Bytes  %       Count  %
Stack                28618  33.51%  306    2.96%
String               14664  17.17%  421    4.07%
GoSyscallBegin        8179   9.58%  1811   17.51%
HeapAlloc             6760   7.92%  1099   10.63%
GoStart               6458   7.56%  1383   13.37%
GoUnblock             5574   6.53%  907    8.77%

スタックとシンボル文字列で 50.68%。イベント数では 7% 程度しかないのにバイト数の半分を持っていきます。goroutine を深いコールスタックから作る設計だと、この比率がさらに上がります。

MaxBytes は上限ではなくヒント

MaxBytes に指定した値は、メモリ使用量の上限として機能しません。

256 KiB 指定で 72 MiB 出た

イベント密度を変えた2種類の負荷で、スナップショットサイズを測りました。低密度は10msごとに20 goroutine、高密度は休みなしで50 goroutine を回し続ける構成です。

負荷      MinAge        MaxBytes         snapshot
low       1s            256 KiB              63.2 KiB
low       1s            1024 KiB             38.0 KiB
low       5s            10240 KiB           181.0 KiB
high      1s            256 KiB           74566.3 KiB
high      1s            1024 KiB          74530.7 KiB
high      100ms         64 KiB            74606.9 KiB

低密度なら指定内に収まります。高密度では MaxBytes=256 KiB に対して 72.8 MiB、指定値の 291倍。64 KiB 指定に至っては 1165倍です。MinAge を 100ms に絞っても変わりません。手元で 1 MiB のつもりで組んだ設定が、負荷の山で70 MiB 側に振れると考えると、常駐プロセスの見積もりとしては危うい。

世代は設定に関わらず丸ごと残る

この挙動は仕様どおりです。FlightRecorderConfig.MaxBytes のコメントが明言しています。

This setting takes precedence over MinAge. However, it does not make any guarantees on the size of the data WriteTo will write, nor does it guarantee memory overheads will always stay below MaxBytes. Treat it as a hint.

理由はリングバッファの捨て方にあります。runtime/trace/recorder.go の endGeneration は、世代(generation)単位でしか古いデータを落としません。

// Add the current generation to the ring. Make sure we always have at least one
// complete generation by putting the active generation onto the new list, regardless
// of whatever our settings are.
newRing := []rawGeneration{r.active}
size := r.active.size
for i := len(r.ring) - 1; i >= 0; i-- {
	// Stop adding older generations if the new ring already exceeds the thresholds.
	if uint64(size) > r.wantSize || now.Sub(newRing[len(newRing)-1].minTime) > r.wantDur {
		break
	}
	size += r.ring[i].size
	newRing = append(newRing, r.ring[i])
}

“regardless of whatever our settings are” の一行が効いています。現在進行中の世代は、どれだけ膨らんでも必ず1つ丸ごと保持される。1世代が72 MiB に育てば、MaxBytes が何であれ72 MiB がメモリに乗ります。

イベント密度が低ければ指定通りに収まる

逆に、1世代ぶんのトレース量が MaxBytes に収まる範囲なら指定は効きます。低密度側の3行がそれ。MinAge を 1秒から5秒に伸ばすと 38.0 KiB が 181.0 KiB になり、期間指定はきちんと反映されました。

見積もりの起点は「1秒あたり何バイト出るか」。-d=footprint でスナップショットの内訳を測り、1世代ぶんの実測値に対して MaxBytes を決めます。逆順で決めると、上の表のように2桁ずれます。

generation の周期を縮めてメモリを抑える

世代が切り替わる周期は runtime/trace.go に定数で入っています。

// traceAdvancePeriod is the approximate period between
// new generations.
const defaultTraceAdvancePeriod = 1e9 // 1 second.

約1秒。つまりトレースデータの最小粒度が1秒ぶんで、MinAge を 100ms に設定してもそれ以下には縮みません。

GODEBUG=traceadvanceperiod で1秒を100msにする

この周期は GODEBUG で変えられます。単位はナノ秒。高密度負荷の3ケースを100ms周期で測り直しました。

GODEBUG=traceadvanceperiod=100000000 go run ./maxbytes

high      1s            256 KiB            6824.9 KiB
high      1s            1024 KiB           6904.1 KiB
high      100ms         64 KiB             6938.9 KiB

74566.3 KiB が 6824.9 KiB へ。約11分の1です。世代あたりのデータ量が10分の1になった結果がそのまま出ています。

ドキュメントの但し書きは古い

runtime/extern.go の GODEBUG 一覧には、traceadvanceperiod に “Only applies if a program is built with GOEXPERIMENT=exectracer2” と書かれています。この実験フラグは Go 1.22 でトレーサ実装がデフォルト化された時点で消えました。go1.26.4 で GOEXPERIMENT を付けずに実測したのが上の結果です。

ただしこの変数の位置づけは「主にテストとデバッグ用」。世代を細かく切るぶん traceAdvance の呼び出し回数が増えるので、本番投入するなら周期短縮ぶんのオーバーヘッドを自分のワークロードで測ってから決めます。

Start と WriteTo の制約

状態遷移まわりの挙動を一通り叩いた結果です。エラーは文言をそのまま載せます。

操作	結果
Start 前に WriteTo	cannot snapshot a disabled flight recorder
Start を2回	cannot enable a enabled flight recorder
2つ目の FlightRecorder を Start	flight recorder already enabled
WriteTo の同時実行	call to WriteTo for trace.FlightRecorder already in progress
Stop 後に WriteTo	cannot snapshot a disabled flight recorder
Stop を2回	no-op (panic しない)
Stop 後に再 Start	成功する
MinAge=1s で300ms時点の WriteTo	成功 (n=4074)
trace.Start と同時に使う	併用可

プロセス内で同時に動かせる Flight Recorder は1つだけ。ライブラリ側で握られると自分のコードから握れなくなるので、アプリケーション側で1箇所に集約しておく設計になります。

オーバーヘッドは常時トレースと変わらない

合成ベンチでは2.13倍

goroutine 生成と channel 通信を極端に多用するワークロードで、トレース無効・Flight Recorder・全期間トレースの3条件を比較しました。ベンチマークは Goのb.Loopで正確なベンチマークを書く—b.Nとの違いと落とし穴 と同じく b.Loop() で回しています。

goos: darwin
goarch: arm64
pkg: gofr/bench
cpu: Apple M5 Pro
BenchmarkNoTrace-18           	   26950	     88276 ns/op
BenchmarkNoTrace-18           	   27098	     88404 ns/op
BenchmarkNoTrace-18           	   27159	     88180 ns/op
BenchmarkFlightRecorder-18    	   12770	    187719 ns/op
BenchmarkFlightRecorder-18    	   12811	    187048 ns/op
BenchmarkFlightRecorder-18    	   12721	    188388 ns/op
BenchmarkFullTrace-18         	   12843	    186773 ns/op
BenchmarkFullTrace-18         	   12778	    187032 ns/op
BenchmarkFullTrace-18         	   12860	    186436 ns/op

Flight Recorder が 2.13倍、全期間トレースが 2.12倍。両者に差はありません。Flight Recorder が削るのはファイルI/Oと保存容量であって、ランタイム側のイベント記録コストは同じものを払います。「フライトレコーダーだから軽い」ではない。

公式の「1-2%」との読み方

公式ブログ More powerful Go execution traces の “Low-overhead tracing” セクションは、Go 1.21 でトレースバック処理が最適化され、CPU オーバーヘッドが 10-20% から 1-2% に下がったと書いています。上のベンチはその数字と2桁ずれています。

上のベンチは1回あたり 88μs の間に goroutine を8個作って500回 channel 送信する、イベント密度だけを狙った合成ケースです。実アプリの比率はこれよりずっと低くなります。同じ環境で HTTPサーバーに3000リクエストを流したときは、トレース無効 7.48秒 / Flight Recorder 7.44秒 / 全期間トレース 7.44秒。ロック待ちが支配的なぶん有意差が出ませんでした。

判断材料は自分のワークロードでの実測値です。goroutine の生成と channel 送受信が多いコードほど、上のベンチの比率に近づきます。

まとめ

• FlightRecorder は Go 1.25 で runtime/trace に追加。直近ぶんをメモリに保持し、WriteTo で吐き出す
• 同一負荷での実測は全期間トレース 1.96 MiB に対しスナップショット 84 KiB。24.1倍の差
• 84 KiB でも go tool trace -pprof=sync でロック待ち 82.29% の犯人まで辿れる
• デフォルト値は MaxBytes 10 MiB、MinAge 10秒。ソースにハードコードされている
• MaxBytes はヒント。世代は設定に関わらず丸ごと残るため、高密度負荷では256 KiB 指定で72.8 MiB まで膨らんだ
• 膨張を抑えるなら GODEBUG=traceadvanceperiod で世代周期を縮める。100ms で約11分の1
• ランタイムのオーバーヘッドは全期間トレースと同じ。軽くなるのは保存側だけ
• プロセス内で同時に有効化できるのは1つ。trace.Start との併用は可

関連して、goroutine が滞留する側の調査は Goのgoroutineリーク対策—pprofとGo 1.26新機能の使い分け、並行処理を決定的にテストする話は testing/synctestでGoの並行処理テストを決定的にする方法 にまとめています。