分散トレーシング

実装: observability/tracing/ / 実行: go test ./observability/tracing/

1つのリクエストは、いくつものサービスを渡り歩く。全体で800ミリ秒かかったとき、どこで時間を使ったかは1台のログを見ても分からない。分散トレーシングは、リクエストに1つの通し番号を振り、各サービスでの処理区間を「番号+誰に呼ばれたか」と一緒に記録して、あとから全行程を復元する。この章ではその記録と受け渡しを実装し、集めた区間を木に組み立てて、全体の時間を決めている連なりを特定する。

この章で作るもの

メトリクスは「システム全体でどれくらい遅いか」を教えてくれる。p99 が 800ms だと分かった。だが「なぜ」は教えてくれない。1 つのリクエストがゲートウェイ・認証・在庫・課金と 4 つのサービスを渡り歩くとき、その 800ms がどこで使われたのか。各サービスのログを別々に見ても、同じリクエストのログを突き合わせる手がかりがない。1 秒間に何千ものリクエストが流れる中で、この 1 本を追うのは干し草の山から針を探すようなものだ。

分散トレーシングはこれを解く。リクエストが入ってきた瞬間に、ただ 1 つの trace_id を振る。以後、そのリクエストがどのサービスに渡ろうと、この trace_id が付いて回る。各サービスは自分の処理を span として記録し、span には trace_id と「誰に呼ばれたか(親の span_id)」を書く。サービスの境界を越えるときは、trace_id と今の span_id をヘッダに詰めて渡す。あとで同じ trace_id の span を集めて親子で組み立てれば、1 リクエストの全行程が 1 本の木になる。

trace_id=1
gateway   ├──────────────────────────────────┤  0-100
auth      │  ├───┤                                10-30
handler   │      ├─────────────────────────┤      30-95
inventory │        ├──┤                            35-50
billing   │           ├──────────────────┤        50-90  ← 遅い
          0   20   40   60   80   100 (ms)

1 リクエストのトレース。全 span が同じ trace_id を共有し、親子で繋がる。横軸は時間で、どの span がいつ走ったかが見える

順に作る。

trace_id で束ねる: リクエストに 1 つの trace_id を振り、全 span が共有する。散らばった記録はこの番号で 1 本に束ねる
親子で木にする: 各 span は親の span_id を持つ。集めて組み立てると呼び出しの木が復元できる
境界を伝播する: サービスを越えるとき trace_id と span_id をヘッダで渡す。別プロセスの span も同じトレースに繋がる

① span と ID: 記録の単位

まず span を定義する。1 つのサービスでの 1 区間の処理だ。自分の span_id、リクエスト全体で共通の trace_id、そして親の span_id を持つ:


// ID は trace / span の識別子。
type ID = uint64

// IDGen は決定的な ID 生成器(テスト再現性のため実乱数を使わない)。
type IDGen struct{ n uint64 }

// NewIDGen は seed から ID 生成器を作る。
func NewIDGen(seed uint64) *IDGen { return &IDGen{n: seed} }

// next は次の ID を返す(0 は「親なし」を表すので 1 から始める)。
func (g *IDGen) next() ID {
	g.n++
	return g.n
}

// Span は 1 つのサービスでの 1 区間の処理。
type Span struct {
	TraceID  ID     // このリクエスト全体で共通
	SpanID   ID     // この span 固有
	ParentID ID     // 親 span(0 なら根 = リクエストの入口)
	Name     string // 何をしていたか(例 "auth.verify")
	Start    int    // 開始の論理時刻
	End      int    // 終了の論理時刻
}

// Duration は span の所要時間。
func (s Span) Duration() int { return s.End - s.Start }

// SpanContext は境界を越えて伝播する最小情報。
// trace_id で「どのリクエストか」、span_id で「誰が親か」を伝える。
type SpanContext struct {
	TraceID ID
	SpanID  ID
}

ID は決定的な生成器から採る。実物はランダムな 128bit などを使うが、ここでは連番にしてテストを再現可能にした。0 を「親なし」の印に予約し、根の span(リクエストの入口)は ParentID が 0 になる。SpanContext は、この後で境界を越えて運ぶ最小の情報だ。trace_id で「どのリクエストか」、span_id で「誰が親になるか」を伝える。この 2 つさえ渡れば、受け取った側は自分の span を正しい位置に繋げられる。

② span を開始・終了する

Tracer が span を開始し、終了時に完了一覧へ集める。根の span は StartRoot で、子は親の SpanContext を渡して Start する。子は trace_id を親から受け継ぎ、親の span_id を自分の ParentID に書く:


// Tracer は span を開始・終了し、完了した span を集めるコレクタ役。
// 時刻は論理時計(Advance で進める)で、テストと決定性のため実時計を使わない。
type Tracer struct {
	ids  *IDGen
	now  int
	open map[ID]*Span // 進行中の span(SpanID → span)
	done []Span       // 完了した span
}

// New は ID 生成器を注入して Tracer を作る。
func New(ids *IDGen) *Tracer {
	return &Tracer{ids: ids, open: make(map[ID]*Span)}
}

// Advance は論理時計を d だけ進める。
func (t *Tracer) Advance(d int) { t.now += d }

// StartRoot は新しいトレースを開始する(親なし = リクエストの入口)。
func (t *Tracer) StartRoot(name string) SpanContext {
	tid := t.ids.next()
	sid := t.ids.next()
	t.open[sid] = &Span{TraceID: tid, SpanID: sid, ParentID: 0, Name: name, Start: t.now}
	return SpanContext{TraceID: tid, SpanID: sid}
}

// Start は parent の下に子 span を開始する。
// trace_id は親から受け継ぎ、親の span_id を ParentID に記録する。
func (t *Tracer) Start(parent SpanContext, name string) SpanContext {
	sid := t.ids.next()
	t.open[sid] = &Span{
		TraceID:  parent.TraceID, // 同じトレース
		SpanID:   sid,
		ParentID: parent.SpanID, // 親を指す
		Name:     name,
		Start:    t.now,
	}
	return SpanContext{TraceID: parent.TraceID, SpanID: sid}
}

// End は span を閉じ、完了一覧に移す。
func (t *Tracer) End(sc SpanContext) {
	s, ok := t.open[sc.SpanID]
	if !ok {
		return
	}
	s.End = t.now
	t.done = append(t.done, *s)
	delete(t.open, sc.SpanID)
}

// Spans は完了した span 一覧を返す(集めた生データ)。
func (t *Tracer) Spans() []Span { return t.done }

// Inject は境界を越えるため SpanContext をヘッダ文字列にする("traceid-spanid")。
// 実物は W3C Trace Context の traceparent ヘッダ。ここでは最小形。
func Inject(sc SpanContext) string {
	return itoa(sc.TraceID) + "-" + itoa(sc.SpanID)
}

// Extract はヘッダ文字列を SpanContext に戻す。壊れていれば false。
func Extract(s string) (SpanContext, bool) {
	i := strings.IndexByte(s, '-')
	if i <= 0 || i == len(s)-1 {
		return SpanContext{}, false
	}
	tid, ok1 := atoi(s[:i])
	sid, ok2 := atoi(s[i+1:])
	if !ok1 || !ok2 {
		return SpanContext{}, false
	}
	return SpanContext{TraceID: tid, SpanID: sid}, true
}

ここに伝播(Inject / Extract)も入れた。あるサービスが別のサービスを HTTP で呼ぶとき、SpanContext をヘッダ文字列にして(Inject)リクエストに載せる。受け取った側はヘッダから復元し(Extract)、それを親として自分の span を始める。プロセスが別でも、ID 生成器が別でも、trace_id と親の span_id さえ伝われば span は 1 つのトレースに繋がる。実物はこれを W3C Trace Context の traceparent ヘッダで標準化していて、ここではその最小形を書いた。

③ 木に組み立て、クリティカルパスを見る

集めた span はただの平らな一覧だ。ここから親子関係で木を組み立て直す。ParentID が指す先を親として繋げば、呼び出しの構造が戻ってくる:


// Node は組み立て直したトレース木の 1 ノード。
type Node struct {
	Span     Span
	Children []*Node
}

// BuildTree は span 一覧を親子で木に組み立てる。根(ParentID==0)を返す。
func BuildTree(spans []Span) *Node {
	byID := make(map[ID]*Node, len(spans))
	for _, s := range spans {
		byID[s.SpanID] = &Node{Span: s}
	}
	var root *Node
	for _, s := range spans {
		n := byID[s.SpanID]
		if s.ParentID == 0 {
			root = n
			continue
		}
		if p, ok := byID[s.ParentID]; ok {
			p.Children = append(p.Children, n)
		}
	}
	return root
}

// CriticalPath は根から「最も遅く終わる子」を辿る鎖を返す。
// 親は子(並列に走ることもある)を待って初めて終われるので、全体の所要時間を
// 決めているのは、各段でいちばん最後に終わる子の連なり = クリティカルパスだ。
// ここを速くしない限り、他をいくら速くしても全体は縮まない。
func CriticalPath(root *Node) []Span {
	var path []Span
	for n := root; n != nil; {
		path = append(path, n.Span)
		var slowest *Node
		for _, c := range n.Children {
			if slowest == nil || c.Span.End > slowest.Span.End {
				slowest = c
			}
		}
		n = slowest
	}
	return path
}

木ができたら、次は「どこが遅いか」を突き止める。ここで見るのがクリティカルパスだ。親 span は、子(並列に走ることもある)がすべて終わって初めて自分を終われる。だから全体の所要時間を決めているのは、各段で最も遅く終わる子の連なりだ。根から「いちばん遅く終わる子」を辿っていくと、全体時間の責任を負う鎖が出る。サンプルのトレースなら gateway → handler → billing。billing が遅い限り、認証や在庫をいくら速くしても全体は縮まない。最適化すべき場所を、勘でなくこの鎖が指す。

テストでこれを固定した。5 つの span を組み、trace_id が全 span で共有されること、親子リンクが正しいこと、クリティカルパスが gateway → handler → billing になることを確かめた。さらに Inject / Extract を挟んでも、別プロセスの span が同じ trace_id と正しい親に繋がることも固定した。

動かす

下のデモは 1 リクエストのトレースを時間軸で描く。各 span を横棒(いつからいつまで走ったか)で並べ、クリティカルパスを強調する。遅いサービスを切り替えると、クリティカルパスがどう変わり、どこを直せば全体が縮むかが見える。

デモ分散トレーシング全体 150ms

課金が遅い認証が遅い在庫が遅い

gateway150

└auth20

└handler115

└inventory15

└billing90

075ms150ms

課金が遅いとき、全体は 150ms。クリティカルパスは gateway → handler → billing。この鎖の上を速くしない限り全体は縮まない。パス外の span をいくら速くしても効かない

1 リクエストが gateway → auth / handler → inventory / billing と渡り歩く様子。全 span が同じ trace_id を共有し、親子で繋がる。強調した棒がクリティカルパス(各段で最も遅く終わる子の連なり)で、全体の所要時間を決めている。遅いサービスを切り替えると、直すべき場所が変わるのが分かる。

設計の観点

trace_id の生成場所: リクエストの最も外側(ゲートウェイやロードバランサ)で 1 度だけ振る。内側で振り直すとトレースが分断される。既に trace_id 付きで来たら引き継ぐ
伝播の標準: 独自ヘッダでなく W3C Trace Context(traceparent)を使う。異なるベンダの計装同士でも繋がる。ここでは仕組みを見るため最小形にした
サンプリングとの関係: 全リクエストの全 span を保存すると量が多すぎる。どれを残すかは Trace Sampling の話。トレーシング(記録の仕組み)とサンプリング(保存の取捨)は別の層
クリティカルパスで狙いを定める: 遅い span を闇雲に直すのでなく、クリティカルパス上の span を直す。パス外の span を速くしても全体は縮まない
オーバーヘッド: 計装は各リクエストにわずかな負荷を足す。span の生成・伝播・送信は軽く保ち、重い属性は必要な span だけに付ける

対照と実例

観測手段	答えられる問い	答えられない問い
メトリクス	全体でどれくらい遅い/多いか	この 1 本がなぜ遅いか
ログ	この瞬間に何が起きたか	複数サービスに跨る流れ
トレース	1 リクエストがどこで時間を使ったか	全体の統計傾向

この 3 つ(メトリクス・ログ・トレース)を可観測性の三本柱と呼ぶ。

裏どり:

Dapper (Google): 分散トレーシングの原典。trace_id・span・親子・サンプリングの基本設計を示した論文。以降の実装はほぼこの子孫
W3C Trace Context: traceparent ヘッダの標準。ベンダ非依存で trace_id と span_id を伝播する
OpenTelemetry: 現在の事実上の標準。span / context propagation / exporter を統一 API で提供。この章の Tracer / Inject / Extract はその最小版
Jaeger / Zipkin / Tempo: 集めた span を保存し、木とタイムラインで可視化するバックエンド

簡略化したこと

論理時計: 実時刻でなく Advance で進める整数。決定性のため
属性・イベントなし: span に付ける tag / log は扱わない
ID は連番: 実物はランダムな 128bit trace_id / 64bit span_id
サンプリングなし: 全 span を保存する。取捨は Trace Sampling で
並行実行なし: 論理時計を手で進めるだけで、実際のゴルーチンは走らせない

参考資料

Dapper, a Large-Scale Distributed Systems Tracing Infrastructure (Google) — 分散トレーシングの原典
W3C Trace Context — traceparent 伝播の標準
OpenTelemetry: Traces — 現行標準の span / 伝播モデル
実装: observability/tracing

分散トレーシング ​

この章で作るもの ​

① span と ID: 記録の単位 ​

② span を開始・終了する ​

③ 木に組み立て、クリティカルパスを見る ​

動かす ​

設計の観点 ​

対照と実例 ​

簡略化したこと ​

参考資料 ​