本セッションの登壇者
セッション動画
「Rustの非同期デバッグツールを使いこなせ!」というタイトルで発表していきたいと思います。
κeenと申します。Twitterなどで騒がしくしている人なので、見たことある人も多いのではないかなと思います。仕事は、Idein Incという会社にいて、しばらくRustを書いている期間がありました。
![](https://res.cloudinary.com/techfeed/image/upload/v1671584179/entries/d2yy9aspyzvxd7yujpps.png)
今日は非同期の話をしていきますが、その前にまず、非同期の話の中にタスクという言葉が出てくるのでそれについて前提を共有したいと思います。
そもそも非同期処理における”タスク”とは
Futureを使って非同期処理を書く際は、async
と await
を使ってつなげていきますよね。たとえば下のコードでは、foo()
という関数と bar()
という関数があって、bar()
関数の中で foo()
関数を呼んでいます。さらに main()
関数では bar()
関数を呼んでいます。これらは async
と await
でつながっていて、1つの実行系列になります。これを1つのタスクと呼ぼうと思います。
![](https://res.cloudinary.com/techfeed/image/upload/v1671671159/entries/pjxi6msfqxlesvq7qdys.png)
このタスクですが、main
だけなら1つですが、tokioの spawn
を呼ぶと新しい実行系列ができてスケジュールも別になります。この場合は新しいタスクができます。たとえば、spawn
以外にも join
も同じですし、ほかにはWebサーバのフレームワークが裏で行っていたりすることもあるので、非同期は意図的か、そうでないにしてもタスクをたくさん作ることになるかと思います。
このタスクの管理が難しいよねというのが今回の主題です。
非同期のデバッグはつらい…
タスクで何かトラブルが起きたときのデバッグがすごい辛いですよね。たとえば、
- どのタスクがどこまで進んでいるのかわからない
- 同時に走っているタスクがわからない
- タスクは動的にスケジューリングされるので休止されるのが普通。なのでデッドロックしているのか、まだスケジューリングされてないのかもわからない
- 仕事で書いたことがある人はわかると思うが、スタックトレースが壊滅する
ということがあります。
![](https://res.cloudinary.com/techfeed/image/upload/v1671671278/entries/l4nvn1r15twrh556znp6.png)
過去に仕事で使っていたアプリケーションのスタックトレースをお見せします。なぜ見せられるかというと、見ても何のことかわからないからです。ずらずらと書いてありますが、この中に私が書いたコードはいっさいありません。
![](https://res.cloudinary.com/techfeed/image/upload/v1671671349/entries/vrs3sksaba4aab6ux1cv.png)
なぜこのようになるかというと、ユーザーが書いた関数がトレースに現れないからです。普通は関数を呼び出した関数はスタックに残っているので、スタックトレースに現れますが、非同期のコードはFutureを返すので、返された時点で関数から抜けてしまいます。なので、スタックにコードが現れません。スタックトレースは実行時エラーを出力しますが、Futureの実行時は、その非同期ランタイムを実行しているタイミングです。
![](https://res.cloudinary.com/techfeed/image/upload/v1671671404/entries/xbiypgqtg0zp93byosmw.png)
このように tokio:runtime
とかのスタックが出てくるだけで、何も役に立ちません。
![](https://res.cloudinary.com/techfeed/image/upload/v1671671455/entries/qsyist2rca12rz5r2hbm.png)
これがとてもつらいので、ツールやライブラリを使って非同期のコードを楽にデバッグできるようにしようというのが今回のお話ですが、いくつかポイントがあるので、分けて説明していきます。
tracing - ログにコンテキストを付与できるトレーシングツール
ひとつはログについてです。ログはデバッグの手段としても、その運用管理としても重要です。しかし非同期タスクの場合、実行が入り乱れるので前後関係が破壊されてしまいます。これをどうにかタスク単位で見れるようにログを分類できると嬉しいですよね。
![](https://res.cloudinary.com/techfeed/image/upload/v1671671524/entries/xbke83npdulwipftpnxx.png)
たとえば、タスク単位で見なかった場合は、サーバがコネクションをacceptする→closeする→リクエストをrecieveしており、順序が矛盾しているのがわかります。
![](https://res.cloudinary.com/techfeed/image/upload/v1671671595/entries/cehzyccazp84uyofm9xj.png)
この問題を解決するためにtracingというクレートがあります。これは、非同期のためのものではないですが、非同期でも有用になるように作られていて、ログにどの文脈で実行されているかのメタデータを加えることができます。
しかし、関数単体では、呼び出したときにしか文脈がわからないので、意外と難しいタスクです。どうやって解決するかというと、 tracingは属性マクロで属性を付加していて、実行時に情報をもらえるようにしているようです。
![](https://res.cloudinary.com/techfeed/image/upload/v1671671654/entries/a55dmygh3kvhqebbxsyl.png)
どういう使い方をするかというと、この instrument
というのが鍵になっていて、関数の前に instrument
を記述します。それから async fn
を定義し、tracing
が info
というマクロを定義しているので、info
をこのように使うことができます。
![](https://res.cloudinary.com/techfeed/image/upload/v1671671702/entries/yiwbwpm77m8wtjgnpr48.png)
ロガーなので、出力設定もあります。その設定はtracing-subscriberというクレートで行えます。これを使うとこんな感じでログレベルなどを設定することができます。
![](https://res.cloudinary.com/techfeed/image/upload/v1671671749/entries/epxkukrxuyjebsu68fyy.png)
こんな感じで実行結果が出力されます。
![](https://res.cloudinary.com/techfeed/image/upload/v1671671791/entries/uupjv9lvytrjvmay4qce.png)
イメージが掴めましたか? 関数に instrument
を付与していき、こういう風にログ( info
や debug
)などを記述します。
![](https://res.cloudinary.com/techfeed/image/upload/v1671672078/entries/ww8nduz5vldkbq5c5kjb.png)
![](https://res.cloudinary.com/techfeed/image/upload/v1671672079/entries/uq10trs8v2waglsfjyqt.png)
実際にデモを行うと、こんな感じになります。parent_task
というのが関数名で、subtask=10
というのが関数の引数です。これらの10個のログが出ており、それに続いて parent_task
から呼ばれた subtask
関数のログが出力されています。これで、どの関数のどの引数から関数が呼ばれてどんなログが出たのかがわかるようになっています。
![](https://res.cloudinary.com/techfeed/image/upload/v1671672143/entries/kefk9pc549wxjolqbxke.png)
あらためて関数を確認すると、main()
関数内で parent_task()
関数を呼んでおり、その parent_task()
の引数が subtask
という形になっていました。parent_task()
の中で subtask
を呼び出しており、subtask
の引数が number
となっています。このように、ログとの整合性を取れるようにしています。
![](https://res.cloudinary.com/techfeed/image/upload/v1671672350/entries/kywsky5umxcu7azzlowi.png)
async-backtrace - プログラム内からスタックトレースのようにタスクの親子関係を表示する
先ほど、スタックトレースが壊滅するという話をしました。そこでもうひとつ問題があります。タスク単位のトレースが欲しいのはもちろんですが、スタックトレースは今実行中のタスクからしか取れなかったら、止まっているタスクのデバッグができません。なので止まっているタスクを含めたすべてのトレースが取得できたら便利ですよね。
![](https://res.cloudinary.com/techfeed/image/upload/v1671672406/entries/xec5bfv1j8ylvzimait1.png)
というわけで、async-backtraceというクレートがあります。こちらもtokioの人が作っています。これは、プログラム内からスタックトレースのようなタスクの親子関係を表示できるようにするものです。エラーが起きたときに出すというよりは、プログラムのデバッグログのような形でスタックトレースを取得する形になります。
![](https://res.cloudinary.com/techfeed/image/upload/v1671672491/entries/v5ytmpisb6gmljdc8hmp.png)
使い方としては、async
の関数に framed
を付与してあげます。最終的にはこういう風に書いてあげます。
![](https://res.cloudinary.com/techfeed/image/upload/v1671672544/entries/dixzgrkqftfh8ljlulas.png)
最終的に async_backtrace::taskdump_tree()
関数を呼んであげるとスタックトレースを出力できます。
![](https://res.cloudinary.com/techfeed/image/upload/v1671672593/entries/mgdpvg3ajqt8kugyvoyh.png)
こちらもデモを試します。asyncな関数にはすべて framed
を付けます。joining()
関数の中で yieldig()
と ready()
をjoinしています。また、スタックが一番深い ready()
の中で taskdamp_tree
を呼んでいます。
![](https://res.cloudinary.com/techfeed/image/upload/v1671672656/entries/izbmrcxix7ysfd2dogf5.png)
これを実行するとどうなるかというと、このように親のタスクが2つの子のタスク(readyとyielding)を作っていることがわかるようになっていて、分岐したタスクも含めて親子関係のツリーを表示してくれます。個人的に ::{{closure}}
が付いているのはイケてないと思いますが、将来的な改善に期待して目を瞑ります。
![](https://res.cloudinary.com/techfeed/image/upload/v1671672914/entries/kkgxcdnwbhs02mnpf141.png)
tokio-console - 活きた情報を見ることができる非同期タスク向けのtop(のようなもの)
最後に、みなさんはtopを使ってパフォーマンスを見たりしませんか? たとえば、サーバのどのプロセスが時間を食っているのか、スレッドモードにするとどのスレッドが…というのもわかるはずです。そういったものを async
のタスクでも見たいのですが、async
のタスクはOSレベルのプロセスやスレッドではないのでtopには出てきません。また、先ほどのようなログツールだと、CPU使用時間などの活きた情報がありません。
![](https://res.cloudinary.com/techfeed/image/upload/v1671672980/entries/v4qn4yknow35m4gjf2x2.png)
そこでtokio-consoleというtopのような、情報を読み出すためのプロトコルでもあるものを使います。
![](https://res.cloudinary.com/techfeed/image/upload/v1671673026/entries/akzxqupksn7bipuy0i1t.png)
使い方はシンプルです。まず、コード内で初期化します。次に、tokioの中でも実験的機能らしいので、--cfg tokio_unstable
を付けてビルドします。
![](https://res.cloudinary.com/techfeed/image/upload/v1671673078/entries/z77umhz2xv7udouowocz.png)
たとえば、ふだんのコードにこのように console_subscriber::init();
と追記してあげるだけです。
![](https://res.cloudinary.com/techfeed/image/upload/v1671673639/entries/kvsulahemziqbuudxkix.png)
これを実行してみましょう。まず、アプリケーションを実行します。tokio-consoleは cargo install
でインストールできます。
![](https://res.cloudinary.com/techfeed/image/upload/v1671673875/entries/j5mgirrvl8loltqyda27.png)
この状態で tokio-console
コマンドを実行すると、タスクのTopのようなものが見えるようになります。
![](https://res.cloudinary.com/techfeed/image/upload/v1671673939/entries/rkdotiwp92wvslxr5aqt.png)
たとえばこのタスクの詳細を見ると、名前やFieldsなどおもしろいものが見れます。ほかにも、Fieldsの並び替えなどもできます。インタラクティブに活きた情報を見れるのがtokio-consoleです。
![](https://res.cloudinary.com/techfeed/image/upload/v1671674133/entries/shcvpcrjemepttu5v3kb.png)
最後にまとめです。
非同期のデバッグはけっこう難しいものです。さまざまな角度から情報を得るために、今回は3つのツールを紹介しました。
- 1つ目はtracingで、これは文脈を付与したログでした
- 2つ目はasync-backtraceで、これはタスクの親子関係を表示してくれます
- 3つ目はtokio-consoleで、これは生きたタスクの情報を表示してくれます
みなさんも、非同期コードのデバッグをするときは、これらのツールを思い出してあげてください。
これで私の発表は以上です。