tracing を使ってコンパイラをデバッグする

コンパイラには多数の debug!（または trace!）呼び出しがあり、多くの箇所でログ情報を出力します。 これらは、バグを完全に見つけるまでには至らなくても少なくとも場所を絞り込むのに非常に役立ちます。また、コンパイラが特定の処理を行っている理由を把握するのにも役立ちます。

ログを見るには、RUSTC_LOG 環境変数をログフィルターに設定する必要があります。 ログフィルターの完全な構文は、tracing-subscriber の rustdocにあります。

環境変数

これは、rustc が tracing 出力をカスタマイズするために受け付ける環境変数の概要です。 これらの定義は、ほとんど compiler/rustc_log/src/lib.rs にあります。

関数レベルのフィルター

rustc の多くの関数には、次のような注釈が付けられています。

#[instrument(level = "debug", skip(self))]
fn foo(&self, bar: Type) {}

これにより、次のように使用できます。

RUSTC_LOG=[foo]

これにより、次のことをすべて一度に行えます。

• foo へのすべての関数呼び出しをログに記録する
• 引数をログに記録する（skip リスト内のものを除く）
• 関数が戻るまで、（コンパイラ内の他の場所からのものを含めて）すべてをログに記録する

すべては不要な場合

関数のスコープによっては、その本体内のすべてをログに記録したくない場合があります。 例として、do_mir_borrowck 関数は、借用チェックされる些細なコードに対しても数百行をダンプします。

すべてのフィルターを組み合わせることができるため、たとえば次のように crate/module パスを追加できます。

RUSTC_LOG=rustc_borrowck[do_mir_borrowck]

すべての呼び出しは不要な場合

libcore をコンパイルしている場合、すべての borrowck ダンプはおそらく不要で、特定の関数に対するものだけが必要でしょう。 関数呼び出しは、引数を正規表現で指定することでフィルタリングできます。

RUSTC_LOG=[do_mir_borrowck{id=\.\*from_utf8_unchecked\.\*}]

これにより、from_utf8_unchecked を借用チェックするログだけが得られます。 無視された do_mir_borrowck ごとに短いメッセージは引き続き表示されますが、それらの呼び出し内の内容は表示されないことに注意してください。 これは、発生している呼び出しを調べるのに役立ち、正規表現を入力し間違えた場合に調整する助けになります。

クエリレベルのフィルター

すべてのクエリには、自動的にロギングスパンがタグ付けされるため、 クエリの実行中のすべてのログメッセージを表示できます。 たとえば、型チェック中のすべてをログに記録したい場合は、次のようにします。

RUSTC_LOG=[typeck]

クエリ引数は tracing フィールドとして含まれます。つまり、引数のデバッグ表示に対してフィルタリングできます。 たとえば、typeck クエリには、何がチェックされているかを示す引数 key: LocalDefId があります。 その LocalDefId に一致する正規表現を使うことで、特定の関数に対する型チェックをログに記録できます。

RUSTC_LOG=[typeck{key=.*name_of_item.*}]

クエリによって引数は異なります。 クエリとその引数の一覧は、rustc_middle/src/queries.rs にあります。

広範なモジュールレベルのフィルター

log crate のフィルターに似たフィルターを使うこともでき、特定のモジュール内のすべてを有効化できます。 これはしばしば冗長すぎ、構造化も不十分になるため、関数レベルのフィルターを使うことを推奨します。

ログフィルターは、すべての debug! 出力以上（たとえば info! も含まれます）を得るために単に debug とすることもできますし、特定のモジュールからのすべての出力（trace! も含まれます）を得るために path::to::module とすることもできます。また、特定のモジュールからの debug! 出力以上を得るために path::to::module=debug とすることもできます。

たとえば、特定のモジュールについて debug! 出力以上を得るには、RUSTC_LOG=path::to::module=debug rustc my-file.rs でコンパイラを実行できます。 すると、すべての debug! 出力が標準エラー出力に表示されます。

部分的なパスを使ってもフィルターは機能することに注意してください。 たとえば、rustdoc::passes::collect_intra_doc_links からの info! 出力だけを見たい場合は、 RUSTDOC_LOG=rustdoc::passes::collect_intra_doc_links=info を使うことも、RUSTDOC_LOG=rustdoc::passes::collect_intra=info を使うこともできます。

rustdoc を開発している場合は、代わりに RUSTDOC_LOG を使ってください。 Miri を開発している場合は、代わりに MIRI_LOG を使ってください。 要領はお分かりでしょう :)

使用できる完全な構文については、tracing crate のドキュメント、特に debug! のドキュメントを参照してください。 （注: コンパイラとは異なり、tracing crate とその例では RUSTC_LOG 環境変数を使用します。 rustc、rustdoc、およびその他のツールはカスタム環境変数を設定します。）

非常に厳密なフィルターを使わない限り、ロガーは大量の出力を生成するため、可能な限り最も具体的なモジュール（複数ある場合はカンマ区切り）を使用してください。 通常は、標準エラー出力をファイルにパイプし、テキストエディターでログ出力を見るのがよいでしょう。

では、まとめると次のようになります。

# これは `rustc_middle/src/traits` 内のすべての debug 呼び出しの出力を
# 標準エラーに送ります。コンソールのスクロールバックを埋め尽くす可能性があります。
$ RUSTC_LOG=rustc_middle::traits=debug rustc +stage1 my-file.rs

# これは `rustc_middle/src/traits` 内のすべての debug 呼び出しの出力を
# `traits-log` に送るので、あとでテキストエディターで確認できます。
$ RUSTC_LOG=rustc_middle::traits=debug rustc +stage1 my-file.rs 2>traits-log

# 推奨しません！これは Rust コンパイラ内のすべての `debug!` 呼び出しの
# 出力を表示します。その数は*非常に多い*ため、何かを見つけるのは
# 難しくなります。
$ RUSTC_LOG=debug rustc +stage1 my-file.rs 2>all-log

# これは `rustc_codegen_ssa` 内のすべての `info!` 呼び出しの出力を表示します。
#
# `codegen_instance` には、codegen されたすべての関数を出力する
# `info!` 文があります。これは、どの関数が LLVM アサーションを
# 引き起こすかを調べるのに役立ちます。また、これは `debug!` ログではなく
# `info!` ログなので、公式コンパイラでも動作します。
$ RUSTC_LOG=rustc_codegen_ssa=info rustc +stage1 my-file.rs

# これは `rustc_codegen_ssa` と `rustc_resolve` 内のすべてのログを表示します。
$ RUSTC_LOG=rustc_codegen_ssa,rustc_resolve rustc +stage1 my-file.rs

# これは rustdoc またはそれが呼び出すすべての rustc ライブラリによる
# すべての `info!` 呼び出しの出力を表示します。
$ RUSTDOC_LOG=info rustdoc +stage1 my-file.rs

# これは rustdoc が直接行った `debug!` 呼び出しのみを表示し、
# `rustc*` クレートによるものは表示しません。
$ RUSTDOC_LOG=rustdoc=debug rustdoc +stage1 my-file.rs

ログの色

デフォルトでは、rustc（および rustdoc や Miri などの他のツール）は、ログ出力で ANSI カラーをいつ使うべきかを賢く判断します。 端末に出力している場合は色を使い、ファイルに出力している場合やどこか別の場所へパイプしている場合は色を使いません。 しかし、非常に厳密なフィルターを設定していない限り、端末でログ出力を読むのは難しいため、less のようなページャーに出力をパイプしたくなることがあります。 しかし、そうすると色がなくなってしまい、探しているものを見つけにくくなります！

ログ出力で色を使うかどうかは、RUSTC_LOG_COLOR 環境変数（rustdoc の場合は RUSTDOC_LOG_COLOR、Miri の場合は MIRI_LOG_COLOR など）で上書きできます。選択肢は 3 つあります: auto（デフォルト）、always、never です。 したがって、less にパイプするときに色を有効にしたい場合は、次のようなコマンドを使います:

# `-R` スイッチは、ANSI カラーをエスケープせずに表示するよう less に指示します。
$ RUSTC_LOG=debug RUSTC_LOG_COLOR=always rustc +stage1 ... | less -R

MIRI_LOG_COLOR は Miri から来るログにのみ色を付け、Miri が呼び出す rustc 関数からのログには色を付けないことに注意してください。 rustc からのログに色を付けるには RUSTC_LOG_COLOR を使ってください。

生成されるバイナリから debug! と trace! の呼び出しを保持または削除する方法

error!、warn!、info! の呼び出しはコンパイラのすべてのビルドに含まれますが、 debug! と trace! の呼び出しは、bootstrap.toml で rust.debug-logging=true が有効になっている場合にのみプログラムに含まれます（デフォルトでは無効です）。そのため、DEBUG ログが表示されない場合、特に RUSTC_LOG=rustc rustc some.rs でコンパイラを実行して INFO ログしか表示されない場合は、bootstrap.toml で rust.debug-logging=true が有効になっていることを確認してください。

ロギングのエチケットと慣習

debug! の呼び出しはデフォルトで削除されるため、ほとんどの場合、「不要な」debug! 呼び出しを追加してコミットするコードに残しておくことによる性能への影響を心配する必要はありません。それらが出荷するものの性能を低下させることはありません。

とはいえ、特に近くにある他の呼び出しやここから呼ばれる関数内の呼び出しと重複している場合は、トレース呼び出しが過剰になることもあります。 ここで達成すべき完璧なバランスはなく、debug! 文を残すことを許可するか、マージ前に削除するよう求めるかは、レビュアーの裁量に委ねられます。

非常に冗長なログには、debug! よりも trace! を使う方が望ましい場合があります。

大まかに守られている慣習として、関数 foo の先頭では debug!("foo(...)") よりも #[instrument(level = "debug")] （属性のドキュメントも参照） を使います。 関数内では、debug!("xyz = {:?}", variable.field) よりも debug!(?variable.field) を、debug!("bar = {:?}", var.method(arg)) よりも debug!(bar = ?var.method(arg)) を好んで使ってください。 この構文のドキュメントはこちらにあります。

注意すべきことの 1 つは、ログ内のコストの高い操作です。

モジュール rustc::foo 内に次の文があるとします。

debug!(x = ?random_operation(tcx));

この場合、誰かが RUSTC_LOG=rustc::foo でデバッグ版の rustc を実行すると、 random_operation() が実行されます。 この debug 文を有効にしない RUSTC_LOG フィルターでは、random_operation は実行されません。

つまり、コストが高すぎるものやクラッシュしそうなものをそこに置くべきではありません。それは、そのモジュールのロギングを使いたい人を困らせることになります。 誰かが別のバグを見つけるためにロギングを使おうとするまで、誰にも分かりません。