Rustで書かれたシステムのトレーシングを実装するtracing

今回はRustの非同期実行とプロセス内のトレーシングの概要を解説したセッションを紹介する。RustはMozilla Foundationがホストするメモリーセーフかつ高速実行を実現するオープンソースのプログラミング言語だ。実際にRustをクラウドネイティブなシステムに利用する場合に避けて通れない機能の一つが非同期実行である。

モノリシックなアプリケーションに比べて、並列化や入出力をブロックしない処理を実装するためには、非同期で実行する仕組みは必須だ。そしてその非同期のプロセスをデバッグする際に必須の機能がトレーシングというわけだ。

これまではシステムやアプリケーションの実行を監視するためにはログが重要視されていたが、非同期かつ並列にプロセスが実行され、プロセスの起動／停止が頻繁に起こるクラウドネイティブの世界では、ログだけでは足らないというのが最近の流れだろう。これまでのモニタリングに加えてログ、メトリクス、トレーシングの3つがクラウドネイティブなシステム監視の要点とされている。

例えばKubernetesは複数のPodが同じサーバーで実行される保証はないし、起動／停止が自動化されているためそれらを監視するためには分散トレーシングが必要とされてきた。その結果、Jaeger、Zipkin、OpenTelemetryなどが開発され、利用されている。

しかし同じメモリー空間に存在するプロセスの並列処理をデバッグするためには、「どの処理がどこまで進んでいるのか？」について可視化するプロセス内のトレーシングの機能が必須だ。複数のPodが連携している間の実行を可視化するのが分散トレーシングなら、今回紹介するのは「インプロセストレーシング」と呼ばれるもので、一つのプロセスから非同期で実行されるサブプロセスのトレーシングを可能にするものだ。

セッションのタイトルスライド

今回紹介するセッションは、2019年8月にポートランドで行われたRustConf 2019において「Tokio-Trace: Scoped, Structured, Async-Aware Diagnostics by Eliza Weisman」と題して発表されたものだ。ちなみにプレゼンテーションを行ったEliza Weisman氏は、サービスメッシュを実装するLinkerdを開発するBuoyantのエンジニアで、RustでLinkerd2-proxyを書いたエンジニアである。

セッションのタイトルにはtokio-traceと書かれているが……

このセッションではRustの非同期ライブラリーであるTokioと、そのサブプロジェクトであるtokio-traceに関するもののはずであったが、冒頭で「tokio-traceではなくtracingだよ」と述べて、タイトルの修正が間に合わなかったことを謝りながら、実際にはTokioとは別のプロジェクトとして「tracing」というライブラリーが開発されており、それに関する解説ということになった。

またWeisman氏は「すでにロギングのライブラリーがあるのに、どうしてまた別のライブラリーを開発するのか？」という問いに対して、これまでのロギングの機能では非同期のプロセスに対して有効ではなかったことを解説した。その際に「これはロギングというよりもインメモリートレーシングと呼ばれるべきもので、どうしてそれが必要になったのかを解説します」としてセッションを続けた。

どうしてロギングではなくインメモリートレーシングが必要なのか

その背景には非同期処理によってログが変化したことが挙げられるという。つまり「ログがシーケンシャルに発生するわけではないこと」「ログが大量に発生すること」などから、ログだけに頼ってシステムを監視することには限界があるというのが現状の認識というわけだ。

非同期は開発も運用も難しい

そしてその難しい非同期処理を監視するために必要なポイントとして挙げられたのがコンテキスト、コーザリティ（Causality、因果関係）そしてストラクチャーだ。コンテキストは日本語では文脈、つまり「エラーログにどのような情報が含まれているのか？」を理解する必要があるということを表している。次のコーザリティ（因果関係）は、エラーやイベントがどのように相関しているかを理解するために必要だ。そして最後のストラクチャーには、ログなどのデータがマシンリーダブル、つまりプログラムから処理しやすいような構造を持つべきだという主張だ。

非同期なシステムの診断に必要なものは何か

これらの解決策として紹介したのがtracingである。以前は「tokio-trace」と呼ばれていたライブラリーだが、今はシンプルに「tracing」と呼ばれている。プロジェクトとしてはTokioのサブプロジェクトであるとしつつも、Tokioのランタイムは必要とせず、Tokioに依存しないで実行できることを強調した。

ログが出力を見ながらフィルターをダイナミックに追加

ここでのデモではWebサーバーが出しているデバッグのためのログを見ながらcurlコマンドで追加のフィルターを適用して、Webサーバーの状態を確認するというものだ。最初に大量に出力されるdebugのメッセージを抑止した上で、404と500のエラーだけを表示させてみせた。

エラーメッセージだけを出力するようにフィルターを適用

さらにエンドポイント「/z」に対するリクエストだけを表示させ、意図的にエラーを返す仕様ではあるものの、実際にエラーをトレースしていることを実演した。

デモはここで終わり、次はtracingがどのようにしてアプリケーションの中のプロセスを監視しているのかを解説することに移った。

実際にトレーシングの内部を解説

そこでJaegerなどの分散トレーシングがノード間の監視であり、明確に分離されているのに対し、インメモリートレーシングもしくはインプロセストレーシングは、同じメモリー空間に存在するプロセスの監視を行うもので、実際にはそれほど違いはないことを解説した。

インプロセストレーシングを解説

tracingの核となるコンポーネントはSpanとEvent、それにSubscriberだ。より詳しくはRustのコンポーネントであるtracingのページを参照して欲しいが、ざっくりと説明するとSpanはトレーシングを行う期間、つまりトレースしたいプロセスの開始から終了を指定するために使われ、Eventは何をトレースするのかを指定し、Subscriberはトレースされたデータを収集するために使われることになる。

SpanとEventがtracingの核となる

トレースされたデータを集めるのはSubscriberの役目

そしてSpan、Event、Subscriberを説明するためにサンプルコードとしてYak ShavingというRustのログ機能の解説で利用されたコードを使った。これは意図的な引用であり、Logとtracingは使われ方が同じであるというのが後半に解説される。

Logの説明に使われたYak Shavingのサンプルコード：https://docs.rs/log/0.4.10/log/index.html#examples

ちなみに「Yak Shaving」とは「大きな問題を解こうとして何かを始めてみたものの、別の小さな問題にぶつかってしまい、無駄な時間を過ごす」ことを指すスラングということで、Yak Shavingでトレーシングを解説することに会場からは笑いが起こっていた。なお、以前にログの説明の時にもYak Shavingをサンプルとして使ったが、その時はYakではなくCowの写真を使ってしまったので「今回はちゃんとYakの写真を使いました」とコメントした。

Yak Shavingを説明するスライドにはちゃんとYakの写真が

Weisman氏はコードを数行ずつ紹介しながら、そのコードが何を行うのかを丁寧に説明した。この例ではSpanがループの中で入れ子になっており、親子関係を持ちながら階層的にトレーシングが行えることを解説した。

Yak Shavingのサンプルコード

最後にトレーシングを行う際に、アプリケーションに対するコストに関する解説を行った。当然、トレーシングを行うためにはその分の処理時間もメモリーも必要となるわけだが、tracingにおいては極力少なくなるように設計されているという。

トレーシングに必要なリソースを最小にするように設計

tracingのリポジトリーであるcrates.ioのtracingのページを紹介し、コントリビューションを求めていることを語った。最後に自身のメールアドレスなどを紹介してセッションを終えた。

コンタクト先などを紹介

tracingのリポジトリー：https://crates.io/crates/tracing

tracingのGitHubページ：https://github.com/tokio-rs/tracing

tracingについて解説したブログ記事：Diagnostics with Tracing

同期型のアプリケーションであればログで充分だが、非同期のアプリケーションにおいてはトレーシングが必須であるというのは説得力があり、それを非同期のためのライブラリーであるTokioの中で実装し、実際にはTokioランタイムなしでも実行できるようにしたのは特記するべきことだろう。今後tracingが、拡大するRustのエコシステムにどのように関わっていくのか、これからも注目していきたい。