すべてが同時に遅くなったならレーンは一本だ

一言でいうと

Nodeでは、JavaScriptは1本のレーンで動きます。そのため「このAPIが遅い」と「全部が遅い」は、たいてい別々の出来事ではなく同じ出来事の二つの顔です。そのレーンがどれだけの時間止まっていたかは、プロファイラーがなくても測れます。

なぜ必要なのか

報告はいつも1か所を指します。「決済確認APIがときどき3秒かかります」。そのAPIのコードを開き、クエリを見て、インデックスを見て、外部呼び出しを見ます。何もおかしくありません。そんなときにすべきなのは、そのAPIをさらに掘り下げることではなく、ほかのAPIのレイテンシも一緒に上がっていないかを見ることです。

一緒に上がっていたなら、犯人はそのAPIではありません。Nodeプロセスの中でJavaScriptを実行するレーンは1本だけで、そのレーンは、いま実行中のコールバックが自分から返すまで、誰にも渡されません。OSが時間を刻んで奪っていくプリエンプティブスケジューリングではなく、各自が自分で譲り合う協調型です。そのため、あるコールバック1つが300msのあいだCPUを握ると、その間に届いたリクエストはすべて300ms待たされます。それらのリクエストのコードには問題がありません。列に並んでいただけです。

この構造は欠陥ではなく、選択です。スレッドをリクエストごとに立ち上げないので、数万の接続を少ないメモリで支えられます。その代わりに、一度に長くかかる仕事をしてはいけないというルールがついてきます。ルールを守れているか確かめるには測る必要があり、だからこのコースの最初の道具はプロファイラーではなく物差しです。

どう動くのか

イベントループは1周をいくつかのフェーズに分けて回ります。タイマー(setTimeout・setInterval)が期限切れになったかを見るフェーズ、完了した入出力のコールバックを呼ぶフェーズ、新しいイベントを待つポールフェーズ、setImmediateを呼ぶチェックフェーズの順です。詳しい順序は公式ガイドのイベントループ、タイマー、process.nextTick()にまとめられています。大切なのはフェーズの名前ではなく、フェーズの間を進むには、いまのコールバックが終わらなければならないという事実です。

測り方はここから導かれます。20msごとに鳴るように設定したタイマーが実際には320ms後に鳴ったなら、その間の300msのあいだ、ループは別の仕事に握られていたことになります。公式ドキュメントも同じ根拠を書いています。「タイマーの実行はlibuvイベントループの寿命に結び付いているため、ループの遅れはそのままタイマーの遅れとして現れる」(perf_hooks)。

let last = Date.now();
setInterval(() => {
  const now = Date.now();
  const lagMs = Math.max(0, now - last - 20);   // 간격을 뺀 나머지가 지연이다
  last = now;
}, 20);

Nodeは同じことをする組み込みのツールも用意しています。perf_hooks.monitorEventLoopDelay()はヒストグラムを作ってくれますが、使うには2つのことを知っておく必要があります。値の単位がナノ秒であること、そしてサンプリング間隔(resolution)のデフォルト値が10msであることです。そのため、何も起きていないプロセスでもこのヒストグラムの中央値は0ではなく10ms付近になります。ラボイメージのNode 22.11.0で測ると、静かな状態のp50は10.5msでした。この値を「私たちのサービスはいつも10msずれている」と読むと、存在しない問題を追うことになります。物差しを自分で作ってみると、その下限がどこから来るのかが実感できます。

現場での姿

この事故の最も厄介な性質は、平均がほとんど動かないことです。1.2秒のあいだ20ms間隔で測ったサンプル44個のうち、100msを超えたのはたった1つで、平均は7.7msでした(Node 22.11.0、2コアでの実測)。平均遅延を描くダッシュボードは、この事故が起きている間も平らなままです。動くのは最大値とp99だけです。

2つ目の性質は、被害者が複数いることです。同じ条件でリクエスト10件を一斉に送り、そのうち3つ目のリクエストだけに300msのあいだCPUを握らせたところ、自分自身を除いた7件も一緒に300ms以上かかりました。ログには遅いリクエストが8件記録され、そのうち本当の原因は1件です。残りの7件のコードをいくら眺めても答えはありません。

そのため、Nodeサービスの障害調査は「遅いエンドポイントを探す」ではなく「同じ時刻に一緒に遅くなったものは何かを見る」から始めるべきです。一緒に遅くなったならレーンが1本だという意味で、次の問いは「そのレーンを誰が握ったのか」の1つだけです。

次のラボですること

遅延の分布を測る物差しを自分で作ります。パーセンタイルの数え方の規則を先に決め、タイマーが遅れた分をサンプルとして集め、同期処理を1回差し込んでテールだけが動くことを確認します。続いてリクエスト10件を一斉に送り、1件の停止が何件を遅らせるかを数え、最後にその数字を「バジェットを何回超えたか」という判断に変えます。

採点ツールは、書き込まれたp50・p99・maxをサンプルから再計算して照合し、作成した関数をもう一度動かして同じ性質が出るかを確かめます。数字だけもっともらしく書いても合格できません。