レッスン4 — Tracing 内部（Reth は自分自身をどう観測しているか）

問い

性能チューニング、デッドロックのデバッグ、ステージが突然止まった理由の診断 — どれも、ノード自身が「何をしているか」を 教えてくれる ことが前提。Reth の答えは tracing crate。Reth の全可観測性（ログ + メトリクス + 分散トレース）が 1 つの基盤から生えている理由は何か？

原理（最小モデル）

• 2 プリミティブ. Span（実行領域、入れ子可）+ Event（ある時点のログ行、span 文脈を引き継ぐ）。
• RUST_LOG で外科的フィルタ. モジュールパス（crate + モジュール階層）でマッチ。本番デバッグは「グローバル warn + 調査対象だけ debug」。
• Subscriber が出力先を決める. fmt（pretty stdout） / json（本番ログ shipping） / opentelemetry（分散トレース） / カスタムレイヤー。
• Async 境界で #[instrument]. span は .enter() で「現在スレッド」にバインド → await で suspend すると span が drop。#[instrument] が future ラッパで suspend を生き残らせる（Rust async tracing バグの第 1 位）。
• メトリクスも同じ基盤. Prometheus メトリクスは tracing event の特定 target を subscribe して counter / histogram に翻訳。
• OpenTelemetry でプロセス境界をまたぐ. OTLP collector がトレース span を集約、N プロセスの完全リクエストパスを 1 つの Jaeger view に。
• debug/trace の hot path コスト. 静的にはコンパイル除外されない（RUST_LOG 無効でもレベルチェック）。revm opcode に debug! を入れると 30% 減速。

具体例

基本パターン（span + event + instrument）:

use tracing::{info, debug, instrument};

#[instrument(skip(self, provider))]
async fn execute(&mut self, provider: &Provider, input: ExecInput) -> Result<ExecOutput> {
    let span = tracing::info_span!("execute", target = ?input.target);
    let _enter = span.enter();

    debug!("starting sender recovery");
    let batches = self.compute_batches(input).await?;
    info!(num_batches = batches.len(), "computed batches");

    for batch in batches {
        let _bspan = tracing::info_span!("batch", n = batch.id).entered();
        process_batch(batch).await?;
        info!("batch committed");
    }
    Ok(...)
}

RUST_LOG フィルタ:

# グローバルに info+、stages モジュールは debug+
RUST_LOG=info,reth_stages=debug cargo run --bin reth -- node

# 特定モジュールの全部
RUST_LOG=reth_exex=trace cargo run --bin reth -- node

# ターゲット組み合わせ
RUST_LOG=info,reth_stages=debug,reth_exex=trace,reth_network=warn

Subscriber テーブル:

Subscriber 初期化:

use tracing_subscriber::{fmt, EnvFilter};

tracing_subscriber::registry()
    .with(EnvFilter::from_default_env())  // RUST_LOG が効く
    .with(fmt::layer())                    // pretty stdout
    .init();

Async 境界で span を生かす:

// 素朴 — span は最初の poll でのみ active
async fn naive(input: Input) {
    let _span = tracing::info_span!("naive").entered();
    do_thing(input).await;  // await が resume する前に span が drop される！
}

// 正しい — span のライフタイムを future 自身に紐づける
async fn correct(input: Input) {
    async {
        do_thing(input).await;
    }.instrument(tracing::info_span!("correct")).await;
}

// またはマクロを使う
#[instrument]
async fn easy(input: Input) {
    do_thing(input).await;
}

OpenTelemetry 統合:

use tracing_subscriber::prelude::*;
use opentelemetry_otlp::WithExportConfig;

let otlp_exporter = opentelemetry_otlp::new_pipeline()
    .tracing()
    .with_exporter(opentelemetry_otlp::new_exporter().tonic().with_endpoint("http://collector:4317"))
    .install_batch(opentelemetry::runtime::Tokio)
    .unwrap();

tracing_subscriber::registry()
    .with(EnvFilter::from_default_env())
    .with(fmt::layer())
    .with(tracing_opentelemetry::layer().with_tracer(otlp_exporter))  // ← OTel export
    .init();

失敗例（誤解）

「.enter() した span は await 越しに有効」— 間違い。.enter() は「現在スレッド」バインド、await で suspend → span drop。Rust async tracing バグの第 1 位。解決は #[instrument] または .instrument(span).await。

「debug! は本番で off だからコストゼロ」— 間違い。レベルチェックは各 event で走る、静的に除外されない。Revm opcode ループに debug! を入れると 30% 減速。hot path は trace! で、本番ビルドの max_level_* feature でコンパイル除外。

🛑 予測。 本番で sender-recovery の停止をデバッグ中、全ログ行は不要（ディスク溢れ）。SenderRecoveryStage が emit するものだけ欲しい。正しい RUST_LOG は？（答え: RUST_LOG=warn,reth_stages::stages::sender_recovery=debug — グローバル warn で他モジュールの致命的問題を捕まえつつ、調査中のステージだけ debug。実際のモジュールパスはリポジトリのバージョンや refactor で変わりうるため、実機ではログ出力元を見て調整する。）

ステップで組み立てる

Step 1: Span と Event を 1 文で

Span = 実行領域（入れ子）/ Event = ある時点のログ行（span 文脈を引き継ぐ）。

Step 2: RUST_LOG を外科的に書ける

warn,reth_stages=debug,reth_exex=trace のような組み合わせ。グローバルベースライン + 調査対象だけ詳細。

Step 3: 4 種 subscriber の使い分け

fmt（開発） / json（本番ログ） / opentelemetry（分散） / カスタム（メトリクスインフラ）。

Step 4: async では必ず #[instrument] か .instrument()

.enter() は await 境界を生き残らない。これを忘れると「バッチ 17 開始 → その後何もない」になる。

Step 5: レベル規律

Step 6: メトリクスと分散トレース

メトリクス: 同じ tracing event の特定 target を subscribe → counter / histogram。 分散トレース: tracing_opentelemetry レイヤー → OTLP collector → Jaeger / Tempo / Datadog APM。

答え合わせ

• tracing が println! より優れる理由: 構造化（key-value で query 可能）+ フィルタ可能（RUST_LOG）+ async-aware（span が await を生き残る）+ 1 基盤がログ + メトリクス + 分散トレースを feed。
• revm opcode に debug! → 30% 減速の理由: debug は静的にコンパイル除外されない（RUST_LOG 無効でもレベルチェックは各 event で走る）。1 ブロック数百万回呼ばれる関数では、チェック自体が測定コスト。→ trace! にして本番ビルドで max_level_* feature で除外。
• メトリクスと tracing の関係: 同じ event ストリームから生える — メトリクスレイヤーが特定 target（例: reth_metrics=info）の event を subscribe して counter / histogram に翻訳。Prometheus エンドポイントが scrape、Grafana で可視化。

合格基準

• Span と Event の違いを即答できる。
• 外科的 RUST_LOG を書ける（warn,reth_stages=debug 形式）。
• 4 種 subscriber の使い分けを言える。
• async で .enter() が壊れる理由と #[instrument] の解決法を説明できる。
• 4 段レベル規律（trace / debug / info / warn）を hot path コストと結びつけて言える。

まとめ（3行）

• tracing = Span（領域）+ Event（時点）の 2 プリミティブ、RUST_LOG で外科的フィルタ、subscriber で出力先決定。
• Async では #[instrument] か .instrument() で span を await 境界越しに生かす（.enter() は drop される）。
• 同じ基盤からログ + メトリクス + 分散トレース全部が生える — これが Reth が println! ではなく tracing を使う構造的理由。