Rustの非同期デバッグツールを使いこなせ! by κeen

本記事は、TechFeed Experts Night#9 〜 Rust/WebAssemblyの「いま」を探る のセッション書き起こし記事になります。イベントページのタイムテーブルから、その他のセッションに関する記事もお読み頂けますので、一度アクセスしてみてください。

本セッションの登壇者

セッション動画

「Rustの非同期デバッグツールを使いこなせ！」というタイトルで発表していきたいと思います。

κeenと申します。Twitterなどで騒がしくしている人なので、見たことある人も多いのではないかなと思います。仕事は、Idein Incという会社にいて、しばらくRustを書いている期間がありました。

今日は非同期の話をしていきますが、その前にまず、非同期の話の中にタスクという言葉が出てくるのでそれについて前提を共有したいと思います。

そもそも非同期処理における”タスク”とは

Futureを使って非同期処理を書く際は、async と await を使ってつなげていきますよね。たとえば下のコードでは、foo() という関数と bar() という関数があって、bar() 関数の中で foo() 関数を呼んでいます。さらに main() 関数では bar() 関数を呼んでいます。これらは async と await でつながっていて、1つの実行系列になります。これを1つのタスクと呼ぼうと思います。

このタスクですが、main だけなら1つですが、tokioの spawn を呼ぶと新しい実行系列ができてスケジュールも別になります。この場合は新しいタスクができます。たとえば、spawn 以外にも join も同じですし、ほかにはWebサーバのフレームワークが裏で行っていたりすることもあるので、非同期は意図的か、そうでないにしてもタスクをたくさん作ることになるかと思います。

このタスクの管理が難しいよねというのが今回の主題です。

非同期のデバッグはつらい…

タスクで何かトラブルが起きたときのデバッグがすごい辛いですよね。たとえば、

どのタスクがどこまで進んでいるのかわからない
同時に走っているタスクがわからない
タスクは動的にスケジューリングされるので休止されるのが普通。なのでデッドロックしているのか、まだスケジューリングされてないのかもわからない
仕事で書いたことがある人はわかると思うが、スタックトレースが壊滅する

ということがあります。

過去に仕事で使っていたアプリケーションのスタックトレースをお見せします。なぜ見せられるかというと、見ても何のことかわからないからです。ずらずらと書いてありますが、この中に私が書いたコードはいっさいありません。

なぜこのようになるかというと、ユーザーが書いた関数がトレースに現れないからです。普通は関数を呼び出した関数はスタックに残っているので、スタックトレースに現れますが、非同期のコードはFutureを返すので、返された時点で関数から抜けてしまいます。なので、スタックにコードが現れません。スタックトレースは実行時エラーを出力しますが、Futureの実行時は、その非同期ランタイムを実行しているタイミングです。

このように tokio:runtime とかのスタックが出てくるだけで、何も役に立ちません。

これがとてもつらいので、ツールやライブラリを使って非同期のコードを楽にデバッグできるようにしようというのが今回のお話ですが、いくつかポイントがあるので、分けて説明していきます。

tracing - ログにコンテキストを付与できるトレーシングツール

ひとつはログについてです。ログはデバッグの手段としても、その運用管理としても重要です。しかし非同期タスクの場合、実行が入り乱れるので前後関係が破壊されてしまいます。これをどうにかタスク単位で見れるようにログを分類できると嬉しいですよね。

たとえば、タスク単位で見なかった場合は、サーバがコネクションをacceptする→closeする→リクエストをrecieveしており、順序が矛盾しているのがわかります。

この問題を解決するためにtracingというクレートがあります。これは、非同期のためのものではないですが、非同期でも有用になるように作られていて、ログにどの文脈で実行されているかのメタデータを加えることができます。

しかし、関数単体では、呼び出したときにしか文脈がわからないので、意外と難しいタスクです。どうやって解決するかというと、 tracingは属性マクロで属性を付加していて、実行時に情報をもらえるようにしているようです。

どういう使い方をするかというと、この instrument というのが鍵になっていて、関数の前に instrument を記述します。それから async fn を定義し、tracing が info というマクロを定義しているので、info をこのように使うことができます。

ロガーなので、出力設定もあります。その設定はtracing-subscriberというクレートで行えます。これを使うとこんな感じでログレベルなどを設定することができます。

こんな感じで実行結果が出力されます。

イメージが掴めましたか? 関数に instrument を付与していき、こういう風にログ( info や debug)などを記述します。

実際にデモを行うと、こんな感じになります。parent_task というのが関数名で、subtask=10 というのが関数の引数です。これらの10個のログが出ており、それに続いて parent_task から呼ばれた subtask 関数のログが出力されています。これで、どの関数のどの引数から関数が呼ばれてどんなログが出たのかがわかるようになっています。

あらためて関数を確認すると、main() 関数内で parent_task() 関数を呼んでおり、その parent_task() の引数が subtask という形になっていました。parent_task() の中で subtask を呼び出しており、subtask の引数が number となっています。このように、ログとの整合性を取れるようにしています。

async-backtrace - プログラム内からスタックトレースのようにタスクの親子関係を表示する

先ほど、スタックトレースが壊滅するという話をしました。そこでもうひとつ問題があります。タスク単位のトレースが欲しいのはもちろんですが、スタックトレースは今実行中のタスクからしか取れなかったら、止まっているタスクのデバッグができません。なので止まっているタスクを含めたすべてのトレースが取得できたら便利ですよね。

というわけで、async-backtraceというクレートがあります。こちらもtokioの人が作っています。これは、プログラム内からスタックトレースのようなタスクの親子関係を表示できるようにするものです。エラーが起きたときに出すというよりは、プログラムのデバッグログのような形でスタックトレースを取得する形になります。

使い方としては、async の関数に framed を付与してあげます。最終的にはこういう風に書いてあげます。

最終的に async_backtrace::taskdump_tree() 関数を呼んであげるとスタックトレースを出力できます。

こちらもデモを試します。asyncな関数にはすべて framed を付けます。joining() 関数の中で yieldig() と ready() をjoinしています。また、スタックが一番深い ready() の中で taskdamp_tree を呼んでいます。

これを実行するとどうなるかというと、このように親のタスクが2つの子のタスク(readyとyielding)を作っていることがわかるようになっていて、分岐したタスクも含めて親子関係のツリーを表示してくれます。個人的に ::{{closure}} が付いているのはイケてないと思いますが、将来的な改善に期待して目を瞑ります。

tokio-console - 活きた情報を見ることができる非同期タスク向けのtop(のようなもの)

最後に、みなさんはtopを使ってパフォーマンスを見たりしませんか? たとえば、サーバのどのプロセスが時間を食っているのか、スレッドモードにするとどのスレッドが…というのもわかるはずです。そういったものを async のタスクでも見たいのですが、async のタスクはOSレベルのプロセスやスレッドではないのでtopには出てきません。また、先ほどのようなログツールだと、CPU使用時間などの活きた情報がありません。