TechFeed Experts Night Pick up

Rustの非同期デバッグツールを使いこなせ! ~TechFeed Experts Night#9講演より

本記事は、2022年11月に開催された「TechFeed Experts Night#9 〜 Rust/WebAssemblyの「いま」を探る」のセッション書き起こし記事「Rustの非同期デバッグツールを使いこなせ! by κeen」を転載したものです。オリジナルはTechFeedをご覧ください。

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

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

自己紹介

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

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

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

非同期処理におけるタスク

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

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

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

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

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

ということがあります。

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

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

スタックトレースの例

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

非同期のコードはスタックトレースから抜ける

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

何も役に立たない

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

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

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

ログ

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

順序が矛盾

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

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

tracingは属性マクロで属性を付加

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

instrumentを記述

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

tracing subscriberを使う

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

tracingデモ

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

コード例1
コード例2

実際にデモを行うと、こんな感じになります。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-backtrace

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

framedを付与するだけ

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

async_backtrace::taskdump_treeを呼ぶだけ

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

デモ:taskdamp_treeを呼ぶ

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

親子関係のツリー表示

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

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

topの問題

そこでtokio-consoleというtopのような、情報を読み出すためのプロトコルでもあるものを使います。

tokio-console

使い方はシンプルです。まず、コード内で初期化します。次に、tokioの中でも実験的機能らしいので、--cfg tokio_unstable を付けてビルドします。

tokio-consoleの使い方

たとえば、ふだんのコードにこのようにconsole_subscriber::init();と追記してあげるだけです。

tokio-consoleの例

これを実行してみましょう。まず、アプリケーションを実行します。tokio-consoleはcargo installでインストールできます。

tokio-console実行:準備

この状態でtokio-consoleコマンドを実行すると、タスクのTopのようなものが見えるようになります。

tokio-console実行

たとえばこのタスクの詳細を見ると、名前やFieldsなどおもしろいものが見れます。ほかにも、Fieldsの並び替えなどもできます。インタラクティブに活きた情報を見れるのがtokio-consoleです。

tokio-consoleの活用

最後にまとめです。

非同期のデバッグはけっこう難しいものです。さまざまな角度から情報を得るために、今回は3つのツールを紹介しました。

  • 1つ目はtracingで、これは文脈を付与したログでした
  • 2つ目はasync-backtraceで、これはタスクの親子関係を表示してくれます
  • 3つ目はtokio-consoleで、これは生きたタスクの情報を表示してくれます

みなさんも、非同期コードのデバッグをするときは、これらのツールを思い出してあげてください。

これで私の発表は以上です。

おすすめ記事

記事・ニュース一覧