本記事は、2022年11月に開催された
「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_というのが関数名で、subtask=10というのが関数の引数です。これらの10個のログが出ており、それに続いてparent_から呼ばれたsubtask関数のログが出力されています。これで、どの関数のどの引数から関数が呼ばれてどんなログが出たのかがわかるようになっています。
あらためて関数を確認すると、main()関数内でparent_関数を呼んでおり、そのparent_の引数がsubtaskという形になっていました。parent_の中でsubtaskを呼び出しており、subtaskの引数がnumberとなっています。このように、ログとの整合性を取れるようにしています。
async-backtrace - プログラム内からスタックトレースのようにタスクの親子関係を表示する
先ほど、スタックトレースが壊滅するという話をしました。そこでもうひとつ問題があります。タスク単位のトレースが欲しいのはもちろんですが、スタックトレースは今実行中のタスクからしか取れなかったら、止まっているタスクのデバッグができません。なので止まっているタスクを含めたすべてのトレースが取得できたら便利ですよね。
というわけで、async-backtraceというクレートがあります。こちらもtokioの人が作っています。これは、プログラム内からスタックトレースのようなタスクの親子関係を表示できるようにするものです。エラーが起きたときに出すというよりは、プログラムのデバッグログのような形でスタックトレースを取得する形になります。
使い方としては、asyncの関数にframedを付与してあげます。最終的にはこういう風に書いてあげます。
最終的にasync_関数を呼んであげるとスタックトレースを出力できます。
こちらもデモを試します。asyncな関数にはすべてframedを付けます。joining()関数の中でyieldig()とready()をjoinしています。また、スタックが一番深いready()の中でtaskdamp_を呼んでいます。
これを実行するとどうなるかというと、このように親のタスクが2つの子のタスクreadyとyielding）::{{closure}}が付いているのはイケてないと思いますが、将来的な改善に期待して目を瞑ります。
tokio-console - 活きた情報を見ることができる非同期タスク向けのtop（のようなもの）
最後に、みなさんはtopを使ってパフォーマンスを見たりしませんか? たとえば、サーバのどのプロセスが時間を食っているのか、スレッドモードにするとどのスレッドが…というのもわかるはずです。そういったものをasyncのタスクでも見たいのですが、asyncのタスクはOSレベルのプロセスやスレッドではないのでtopには出てきません。また、先ほどのようなログツールだと、CPU使用時間などの活きた情報がありません。
そこでtokio-consoleというtopのような、情報を読み出すためのプロトコルでもあるものを使います。
使い方はシンプルです。まず、コード内で初期化します。次に、tokioの中でも実験的機能らしいので、--cfg tokio_ を付けてビルドします。
たとえば、ふだんのコードにこのようにconsole_と追記してあげるだけです。
これを実行してみましょう。まず、アプリケーションを実行します。tokio-consoleはcargo installでインストールできます。
この状態でtokio-consoleコマンドを実行すると、タスクのTopのようなものが見えるようになります。
たとえばこのタスクの詳細を見ると、名前やFieldsなどおもしろいものが見れます。ほかにも、Fieldsの並び替えなどもできます。インタラクティブに活きた情報を見れるのがtokio-consoleです。
最後にまとめです。
非同期のデバッグはけっこう難しいものです。さまざまな角度から情報を得るために、今回は3つのツールを紹介しました。
- 1つ目はtracingで、これは文脈を付与したログでした
- 2つ目はasync-backtraceで、これはタスクの親子関係を表示してくれます
- 3つ目はtokio-consoleで、これは生きたタスクの情報を表示してくれます
みなさんも、非同期コードのデバッグをするときは、これらのツールを思い出してあげてください。
これで私の発表は以上です。