Node.jsの短時間の非同期関数でもイベントループをブロックすることがある
Michael Gokhman
2019年2月4日
0 分で読めます一般的なNode.jsアプリは、基本的にさまざまなイベント(接続の受信、I/Oの完了、タイムアウト、Promiseの解決など)に応じて実行されるコールバックの集合体です。これらすべてのコールバックを実行するメインスレッド(別名イベントループ)は1つしかないため、ほかの保留中のコールバックが順番を待つことのないよう、コールバックはすぐに完了する必要があります。これはNodeのよく知られた難しい制約であり、ドキュメントでもわかりやすく説明されています。
最近、Snykで実際にイベントループがブロックされる状況に遭遇しました。この状況を解決しようとしたとき、イベントループの挙動について自分がほとんど何も知らなかったことに気づきました。また、同じ話を共有した開発者仲間とともに、最初は驚くような発見もありました。できるだけ多くのNode開発者にこの知識を知ってもらうことが大切だと考え、この記事を書くことにしました。
Node.jsのイベントループについては、すでに役立つ情報がたくさんあります。しかし、自分が知りたかった具体的な疑問への答えを見つけるまでには時間がかかりました。私が抱いたさまざまな疑問と、優れた記事や楽しい実験、調査を通じて見つけた答えを、できるだけ共有したいと思います。
まず、Node.jsのイベントループをブロックしてみましょう!
注:
以下の例では、2017年製MacBook Pro上で動作する4コアのUbuntu 18.04 VMに、Node 10.9.0を使用しています
以下のコードは、こちらをクローンして試せます https://github.com/michael-go/node-async-block
まずはシンプルなExpressサーバーから始めましょう。
次に、厄介なイベントループブロック用のエンドポイントを追加します。
そのため、/compute-syncエンドポイントの処理中は、/healthcheckへのリクエストが滞ると予想できます。次のbashワンライナーで/healthcheckを確認できます。
毎秒/healthcheckエンドポイントを確認し、5秒以内に応答がなければタイムアウトします。
試してみましょう。

/compute-syncエンドポイントを呼び出した途端、ヘルスチェックはタイムアウトし始め、1件も成功しなくなりました。nodeプロセスがCPUを約100%使ってフル稼働していることにも注目してください。

43.2秒後に計算が終了すると、保留中だった/healthcheckへの8件のリクエストが処理され、サーバーは再び応答するようになります。
これはかなり深刻な状況です。厄介なリクエスト1件でサーバー全体がブロックされます。「シングルスレッドのイベントループ」という知識があれば、/compute-syncのコードがほかのすべてのリクエストをブロックした理由は明らかです。処理が完了するまでイベントループのスケジューラーに制御を戻さなかったため、/healthcheckのハンドラーが実行される機会がありませんでした。
ブロックを解消しましょう!
/compute-asyncという新しいエンドポイントを追加し、長時間かかるループを処理ステップごとに分割して、イベントループに制御を戻すようにします(コンテキストの切り替えが多すぎるかもしれませんが、後から最適化してX回の反復ごとに一度だけ制御を戻すこともできます。まずはシンプルに始めましょう)。
試してみましょう。

うーん……まだイベントループがブロックされますね?

どうなっているのでしょう?Node.jsが、ここでのおもちゃのようなasync/awaitの使用を最適化で取り除いているのでしょうか?処理の完了にはさらに数秒かかったので、そうではなさそうです……asyncが実際に有効だったかどうかは、フレームグラフで手がかりが得られます。こちらの便利なGitHubプロジェクトを使えば、簡単にフレームグラフを生成できます。
まず、/compute-syncの実行中に取得したフレームグラフです。

/compute-syncのスタックにはExpressのハンドラースタックが含まれていることがわかります。処理が完全に同期的だったためです。
次に、/compute-asyncの実行中に取得したフレームグラフです。

一方、/compute-asyncのフレームグラフは大きく異なり、V8のRunMicrotaskとAsyncFunctionAwaitResolveClosure関数のコンテキストで実行されています。つまり……async/awaitが「最適化で取り除かれた」わけではなさそうです。
さらに掘り下げる前に、開発者がときどきやる最後の手段を試しましょう。sleep呼び出しを追加します!
実行してみましょう。

ようやく、重い計算中もサーバーが応答し続けるようになりました。しかし、この解決策の代償は大きすぎます。CPU使用率は約10%で、計算が十分に進んでいないようです。実際、完了までにいつまでもかかりそうです(完了を見届けるほど待てませんでした)。反復回数を10⁷から10⁵に減らして、ようやく2分23秒後に完了しました!(ちなみに、setTimeoutの遅延パラメーターに0ではなく1を渡しても違いはありません。この点は後ほど説明します)
ここで、いくつかの疑問が浮かびます。
なぜ
asyncコードはsetTimeout()呼び出しがないとブロックされたのでしょうか?なぜ
setTimeout()を追加すると、パフォーマンスが大幅に低下したのでしょうか?このようなペナルティなしで、計算のブロックを解消するにはどうすればよいのでしょうか?
イベントループのフェーズ
同じような状況に遭遇したとき、答えを求めてGoogleで検索しました。「node async block event loop」のような検索語で調べると、最初に見つかる結果の1つが、このNode.js公式ガイドです。目からうろこでした。
このガイドによると、イベントループは想像していたような魔法のスケジューラーではなく、いくつかのフェーズで構成される、かなり単純なループです。ガイドから引用した、主なフェーズを示すASCII図を紹介します。

(後になって、このループはlibuvで図と同じ名前の関数を使って実装されていることがわかりました。https://github.com/libuv/libuv/blob/v1.22.0/src/unix/core.c#L359)
このガイドでは各フェーズについて説明し、次のようにまとめています。
timers:
setTimeout()とsetInterval()でスケジュールされたコールバックを実行します。pending callbacks:次のループ反復まで延期されたI/Oコールバックを実行します。
idle、prepare:内部処理でのみ使用されます。
poll:新しいI/Oイベントを取得し、I/O関連のコールバックを実行します。
check:ここで
setImmediate()のコールバックが呼び出されます。close callbacks:
socket.on('close', ...)など、一部のクローズコールバックを実行します。
疑問への答えの手がかりとなるのは、次の一節です。
「一般に、イベントループが特定のフェーズに入ると、そのフェーズに固有の処理を行い、キューが空になるまで、そのフェーズのキュー内のコールバックを実行する……これらの処理によって新たな処理がスケジュールされることもあるため……」
この説明から(おぼろげながら)わかるのは、あるコールバックが同じフェーズで処理できる別のコールバックをキューに追加した場合、次のフェーズに進む前にそれが処理されるということです。
Node.jsが新しいリクエストをネットワークソケットで確認するのはpollフェーズだけです。つまり、/compute-asyncで行ったことによって、イベントループが特定のフェーズから抜け出せず、pollフェーズを経由して/healthcheckリクエストを受け取ることもできなかったのでしょうか?
より確かな答えを得るには、さらに調べる必要があります。しかし、setTimeout()が役立った理由ははっきりしました。タイマーコールバックをキューに追加し、現在のフェーズのキューが空になるたびに、イベントループはすべてのフェーズを経由して「Timers」フェーズに戻る必要があります。その途中でpollフェーズを通り、保留中のネットワークリクエストを処理します。
マイクロタスク
/compute-asyncで使ったasync/awaitキーワードは、Promiseを使った構文糖衣として知られています。つまり実際には、ループの各反復でハッシュを計算するためのPromise(非同期処理)を作成し、それが解決されると次の反復に進みます。先ほどの公式ガイドでは、イベントループの各フェーズにおいてPromiseがどのように処理されるかは説明されていません。しかし、実験結果からは、Promiseのコールバックもresolveのコールバックも、pollフェーズを経由せずに呼び出されていたことがわかります。
さらにGoogleで調べると、Deepal Jayasekaraによるイベントループについての、詳しくてとても読みやすい全5回の記事を見つけました。Promiseの処理についても説明されています。
そこには、次のような便利な図があります。

円の周りのボックスは前に見た各フェーズのキューを示し、中央の2つのボックスは、あるフェーズから別のフェーズに移る前に空にする必要がある、特別な2つのキューを示しています。「next tick queue」はnextTick()で登録されたコールバックを処理します。「Other Micro Tasks queue」は、Promiseについての疑問への答えです。
今回のケースのように、解決済みのPromiseが別のPromiseを作成した場合、それは次のフェーズに進む前に同じフェーズで処理されるのでしょうか?答えは、見たとおり「はい」です!この仕組みはV8のソースコードで確認できます。このリンクはRunMicrotask()の実装を示しています。関連する行を抜粋して紹介します。
このCコードは奇妙に見えます。Goto()やBranch()といった低レベルの関数/マクロを使い、魔法のようにループ処理をしています。V8の「CodeStubAssembly」で記述されているためです。これは「アセンブリを薄く抽象化し、低レベルのプリミティブを提供する、プラットフォームに依存しない独自のアセンブラ」です。
gistを見ると、init_queue_loopというラベルの外側のループと、loopというラベルの内側のループがあります。外側のループは保留中のマイクロタスク数を確認し、内側のループはタスクを1つずつ処理します。すべて処理し終えると、上のgistの62行目にあるように外側のループを繰り返し、保留中のマイクロタスク数を再確認します。新しいタスクが追加されていない場合に限り、関数が戻ります。
イベントループの各フェーズの終了時にマイクロタスクがどのように処理されるか知りたい方には、Deepal Jayasekaraによるこちらの優れた記事もおすすめします。
(ちなみに、/compute-async用に作成したフレームグラフを覚えていますか?上に戻って見直すと、スタック内にRunMicrotasks()があるのがわかります)
また、マイクロタスクはV8の機能であるため、Chromeにも当てはまる点に注目してください。ChromeでもPromiseは同じように処理され、ブラウザーのイベントループは回りません。
nextTick()では次のティックに進まない
Node.jsガイドには、次のように書かれています。
process.nextTick()に渡されたコールバックは、イベントループが続行する前に解決されます。これにより、process.nextTick()を再帰的に呼び出してI/Oを「飢餓状態」にできるため、問題が起きることがあります。
今回は説明から明らかなので、ターミナルのスクリーンショットは省きますが、node async blockでGET /compute-with-next-tickを実行して試せます。
nextTickキューの処理箇所はこちらです。
callbackが別のprocess.nextTick()を呼び出すと、ループは同じループ内で次のコールバックを処理し、nextTickキューが空になったときにだけ終了することがわかります。
setImmediate()で解決できる?
つまり、Promiseは赤、タイマーは青――ほかにできることは何でしょうか?
上の図を見ると、どちらにも「check」フェーズで、つまり「poll」フェーズの直後に処理されるsetImmediate()キューがあります。Node.jsの公式ガイドにも、次のように書かれています。
setImmediate()とsetTimeout()は似ていますが、呼び出すタイミングによって挙動が異なります……
setTimeout()よりsetImmediate()を使う主なメリットは、I/Oサイクル中にスケジュールされると、タイマーの数にかかわらず、常にタイマーより先にsetImmediate()が実行されることです。
よさそうですが、特に期待できるのは次の一節です。
pollフェーズがアイドル状態になり、
setImmediate()でスクリプトがキューに追加されている場合、イベントループは待機せずにcheckフェーズへ進むことがあります。
setTimeout()を使ったとき、プロセスがほとんどアイドル(つまり待機中)で、CPU使用率が約10%だったのを覚えていますか?setImmediate()で解決できるか、見てみましょう。

やった!サーバーをブロックせず、CPU使用率は100%です!完了までにどれくらいかかるか見てみましょう。

いいですね。完了まで1分7秒かかりました。/compute-syncより約50%、/compute-async より34%長くかかっていますが、/compute-with-set-timeoutとは違って実用できます。おもちゃのような例とはいえ、10⁷回の短い反復それぞれでsetImmediate()を使っており、おそらくイベントループを10⁷回完全に回したことを考えれば、この遅さも納得できます。つまり、setImmediate()のコールバック内からsetImmediate()をスケジュールしても、同じフェーズにとどまるわけではないのでしょうか?そのとおりです。Node.jsのドキュメントには、次のように明記されています。
実行中のコールバック内から即時タイマーがキューに追加された場合、そのタイマーは次のイベントループの反復まで実行されません。
setImmediate()とprocess.nextTick()を比較すると、Node.jsのガイドには次のようにあります。
どのような場合でも
setImmediate()を使うことをおすすめします…
コードへの参照はすでにご覧いただいているので、期待を裏切らないように言うと、これがsetImmediate()コールバックを実行する実際のコードだと思います。ちなみに、Deepalのシリーズ第3回で紹介されている興味深い事実ですが、人気のある非ネイティブPromiseライブラリであるBluebirdは、PromiseコールバックのスケジュールにsetImmediate()を使っています。
まとめ
(ボーナスセクションとしてsetTimeout()についてもこの後説明します)さて、setImmediate()は、時間のかかる同期コードを分割する方法として有効なようです。しかし、いつも簡単に適切に実装できるとは限りません。setImmediate()に処理を譲るたびにオーバーヘッドが発生します。また、保留中のリクエストが増えるほど、時間のかかるタスクの完了にも時間がかかります。そのため、コードを細かく分割しすぎても問題ですし、分割が少なすぎると長時間ブロックする可能性があります。場合によっては、例のような単純なループではなく、複雑な構造をたどる再帰処理がコードをブロックすることもあり、処理を譲る適切な場所や条件を見つけるのがさらに難しくなります。状況によっては、setImmediate()に処理を譲るまでにブロックしていた時間を記録しておく方法も考えられます。このコードは、前回処理を譲ってから少なくとも10msが経過した場合にのみ、処理を譲ります。
また、制御しにくいサードパーティー製コードがブロックすることもあります。JSON.parse()のような組み込み関数でさえ、ブロックする可能性があります。
より抜本的な方法として、ブロックする可能性のあるコードを別の(Node.js以外の)サービスやサブプロセス(tiny-workerなどのパッケージを使用)、あるいはwebworker-threadsのようなパッケージや(まだ実験段階の)Node.js組み込みのworker-threadsを使って実際のスレッドにオフロードする方法があります。多くの場合、これは適切な解決策ですが、オフロードしたコードはメイン(唯一の)JSスレッドのコンテキストにアクセスできないため、シリアライズしたデータをやり取りする必要があり、どの方法にもその手間が伴います。
こうした解決策に共通する課題は、ブロックを回避する責任がOS(多くのスレッド型言語の場合)やランタイムVM(Erlangの場合)ではなく、開発者一人ひとりに委ねられていることです。すべての開発者が常にこの点を意識するよう徹底するのは難しいだけでなく、保留中のほかの処理やI/Oの状況を把握できないコードから、明示的に処理を譲るのが最適ではない場合も少なくありません。
Node.jsが実現する高スループットも、適切に扱わなければ、1つのブロッキング処理によって多数のリクエストがキューに並び、待たされることになります。遅延しているリクエストが大量にあることをできるだけ早くロードバランサーに知らせ、別のノードにリクエストを振り分けられるよう、ヘルスチェックのエンドポイントでtoobusy-jsなどのパッケージを使ってみてください(実際にブロックしている間は役に立ちませんが…)。また、blocked-atのようなパッケージやN|Solid、New Relicなどのソリューションを使って、実行時にイベントループを監視することも重要です。
ボーナス:setTimeout(0)の0が本当は0ではない理由
setTimeout(0)を使うと、計算を続けるのではなくプロセスが90%もアイドル状態になるのはなぜなのか、とても気になりました。CPUがアイドル状態ということは、nodeのメインスレッドがシステムコールを呼び出し、実行を一時停止(つまりスリープ)していた時間が、カーネルによって再開されるまで十分に長かったということでしょう。つまり、setTimeout()が関係していそうです。
タイマー処理に関するlibuvのソースコードを読むと、実際の「スリープ」は、timeoutパラメーターを介してシステムコールpoll()の一部として呼び出されるuv__io_poll()で発生するようです。
poll()のmanページには、次のようにあります。
timeout引数は、ファイルディスクリプターが準備完了になるまでpoll()が待機してブロックする時間(ミリ秒)を指定します。timeoutに負の値を指定すると、タイムアウトは無限になります。timeoutに0を指定すると、poll()は直ちに戻ります。
つまり、タイムアウトが正確に0でない限り、プロセスはスリープします。setTimeout()に0を渡しても、実際にはpoll()に渡されるタイムアウトはそれより大きいのではないかと考えられます。gdbを使ってnode自体をデバッグし、確かめてみましょう。
gdbのdprintfコマンドを使えば、uv__io_poll()のすべての呼び出しをトレースできます。
各トレースで現在時刻も出力してみましょう。


サーバーの起動時、uv__io_poll()はタイムアウト-1で呼び出されます。これは「無限タイムアウト」を意味します。HTTPリクエストを待つ以外にすることがないためです。では、/compute-with-set-timeoutエンドポイントにGETリクエストを送ってみましょう。
ご覧のとおり、タイムアウトは1になることもあります。また、0になる場合でも、連続する呼び出しの間に通常は少なくとも1ms経過しています。同じ方法で/compute-with-set-immediateにGETリクエストを送ってデバッグすると、常にtimeout=0と表示されます。

CPUにとって、1ミリ秒はかなり長い時間です。/compute-syncのタイトなループは10⁷回の反復を43秒で完了しました。つまり、1ミリ秒あたり約233回のランダムなハッシュ計算を実行したことになります。各反復で1ms待つと、合計10,000秒、つまり2時間45分もかかります。
uv__io_poll()に渡されるタイムアウトが0ではない理由を考えてみましょう。タイムアウトはuv_backend_timeout()で計算され、libuvのメインループに示されているようにuv__io_poll()に渡されます。保留中のアクティブハンドルやリクエストがある場合などはuv_backend_timeout()は0を返します。それ以外の場合はuv__next_timeout()の戻り値を返します。この関数は「タイマーヒープ」から最も近いタイムアウトを選び、その期限までの残り時間を返します。
「タイムアウト」を「タイマーヒープ」に追加する関数はuv_timer_start()です。この関数は多くの箇所から呼び出されるため、このケースでゼロ以外の値を渡している呼び出し元を特定しやすくするために、ブレークポイントを設定してみましょう。ブレークポイントでGDBのinfo stackコマンドを実行すると、次のように表示されます。
TimerWrap::Startはuv_timer_start()を薄くラップしただけの関数です。スタック上部にある判読できないアドレスから、探している実際のコードはおそらくJavaScriptで実装されていることがわかります。NodeのソースコードでTimerWrap:Startの使用箇所を探すか、JSデバッガーでJS側からsetTimeout()の実装に「ステップイン」すれば、https://github.com/nodejs/node/blob/v10.9.0/lib/internal/timers.js#L53にあるTimeoutコンストラクターをすぐに見つけられます。
最後に、タイムアウトの0が1にまとめられていることがわかります。
この記事がお役に立てば幸いです。お読みいただき、ありがとうございました。
参考資料:
https://nodejs.org/en/docs/guides/event-loop-timers-and-nexttick/
https://github.com/libuv/libuv(nodejs/nodeにも同梱)
https://github.com/v8/v8(nodejs/nodeにも同梱)
このテーマについてさらに読む:
https://javabeginnerstutorial.com/node-js/event-loop-and-asynchronous-non-blocking-in-node-js/
https://stackoverflow.com/questions/34824460/why-does-a-while-loop-block-the-event-loop
https://stackoverflow.com/questions/46004290/will-async-await-block-a-thread-node-js
https://stackoverflow.com/questions/51694299/node-js-socket-io-async-and-blocking-event-loop
http://voidcanvas.com/setimmediate-vs-nexttick-vs-settimeout/
http://dtrace.org/blogs/brendan/2012/11/14/dtracing-in-anger/
https://developer.mozilla.org/en-US/docs/Web/JavaScript/EventLoop
https://jakearchibald.com/2015/tasks-microtasks-queues-and-schedules/ - ブラウザー
https://blog.risingstack.com/node-js-at-scale-understanding-node-js-event-loop/
https://humanwhocodes.com/blog/2013/07/09/the-case-for-setimmediate/
