ループが止まった時間を測る物差しを作る

目標

イベントループがどれだけの時間止まっていたかを測る物差しを自分で作り、同期処理1回がそのプロセスのすべてのリクエストをどのようにまとめて遅らせるかを数字で確認します。

なぜ重要なのか

「APIが遅い」という報告が入ると、たいていそのAPIのコードを先に見ます。ところがNodeでは、犯人が別の場所にいることがよくあります。 JavaScriptを実行するレーンは1本だけなので、あるリクエスト1つがそのレーンを300msのあいだ握ると、その間に届いたすべてのリクエストが一緒に300ms遅れます。遅くなったAPIのコードには何の問題もありません。

そのため、このコースの最初の道具はプロファイラーではなく物差しです。一定の間隔で鳴るように設定したタイマーがどれだけ遅れて鳴ったかを見れば、その間にループがほかの仕事に握られていた時間がわかります。平均はほとんど動かず、テールだけが動くというのがこの分布の核心で、平均だけを見るダッシュボードがこの事故を捉えられない理由です。

ステップ

/root/work/loop/lag.mjsにpct(samples, p)を作ります。
同じファイルにsample({durationMs, intervalMs})を作ります。
何もさせずに測り、/root/work/loop/report.jsonのruns.idleに書きます。
blockFor(ms)を作り、測っている途中で1回だけ塞いでruns.blockedに書きます。
100msを超えたサンプルの個数と割合、そして平均をruns.blockedに追加します。
queue({n, serviceMs, blockAt, blockMs})で複数のリクエストを一斉に処理し、 runs.queueに書きます。
verdict(run, budgetMs)で、バジェットを超えたサンプルを数える規則を作ります。

参考

パーセンタイルは最近傍順位(nearest-rank)で数えます。昇順に並べ替えたあとのceil(p/100 * n) - 1番目の値で、範囲を外れたら両端に寄せます。採点ツールが同じ規則で再計算して照合します。
遅延は測った間隔を引いた残りです。経過時間をそのまま入れると、静かな状態でも中央値が間隔の分だけ出ます。
report.jsonのnodeフィールドには、このPodのバージョン(process.version)を書きます。
よくある間違いは、塞いでいる間もサンプルが溜まると考えることです。ループが止まるとタイマーも止まるため、その区間はサンプル1つの大きな値として現れます。

パーセンタイルの規則を先に決める

/root/work/loop/lag.mjsにpct(samples, p)をexportしてください。最近傍順位の規則を使い、渡された配列を並べ替えて書き換えてはいけません。

並べ替えはコピーに対して行います。[...samples].sort((a, b) => a - b)から始めてください。

順位はMath.ceil(p / 100 * n) - 1で、0より小さいか、nを超える場合は両端に寄せます。p99が最大値と同じになるような小さなサンプルは正常です。

タイマーが遅れた分がループの止まった時間になる

同じファイルにsample({durationMs, intervalMs})をexportしてください。{intervalMs, durationMs, samples}を含むPromiseを返し、samplesには間隔を引いた遅れの時間をmsで入れます。

setIntervalでintervalMsごとに起きて、前回起きた時刻との差からintervalMsを引きます。負の値は0に丸めます。

durationMsが経過したらclearIntervalして結果を返します。採点ツールがこの物差しを使って自分でループを塞いでみるので、実際の時刻を測る必要があります。

何も起きていないときのベースライン

何もさせずに1秒以上測り、/root/work/loop/report.jsonにnodeとruns.idleを書いてください。runs.idleにはintervalMs・durationMs・samples・p50・p99・maxを入れます。

ベースラインがないと、あとで測った数字が大きいのか小さいのか言えません。

p50・p99・maxは自分で作ったpctで計算して書きます。採点ツールがsamplesから再計算して照合するので、手で直すと不合格になります。

1回塞いで、もう一度測る

blockFor(ms)をexportし(その時間のあいだ実際に握る必要があります)、測っている途中でblockFor(300)を1回だけ入れてruns.blockedに書いてください。blockMsも一緒に入れます。

setTimeout(() => blockFor(300), 300)のように、測り始めたあとに1回だけ塞ぎます。

await new Promise(r => setTimeout(r, ms))は塞ぐことにはなりません。待っている間、ループは自由です。ここではCPUを握っている側が必要です。

平均はなぜ何も言わないのか

runs.blockedにover100(100msを超えたサンプル数)、over100Ratio(小数第4位まで)、mean(平均)を追加してください。

300msを1回塞いだとき、100msを超えたサンプルが何個か数えてみてください。

その1つのせいであるリクエストは丸ごと止まったのに、平均はほとんどそのままです。平均だけを見るダッシュボードがこの事故を捉えられない理由が、この2つの数字にあります。

遅くなったのは1つのリクエストではなかった

queue({n, serviceMs, blockAt, blockMs})をexportしてください。リクエストn件を一斉に開始してそれぞれserviceMsだけ待ち、blockAt番目だけをblockFor(blockMs)で塞いだあと、リクエストごとのレイテンシ(ms)の配列を返します。n=10・serviceMs=20・blockAt=2・blockMs=300で測り、runs.queueにlatencies・p50・p99・victimsを書いてください。

victimsは、塞いだリクエストを除き、レイテンシがblockMs * 0.8以上のリクエストの数です。

一斉に開始するとは、Promiseをすべて作っておいてPromise.allで待つという意味です。forの中でawaitすると1件ずつ順番に処理したことになり、そうするとこのラボが見せようとしていることが消えてしまいます。

測った値を判断に変える

verdict(run, budgetMs)をexportしてください。run.samplesから、バジェットを超えた(同じ値は超えたことになりません)サンプルを数えて{ok, worst, breaches}を返します。サンプルがなければworstは0です。

境界値をどちら側に入れるか決めておかないと、人によって違う答えが出ます。ここでは> budgetMsだけが違反です。

この関数があれば、「遅延が少しありますね」ではなく「バジェット100msを3回超え、最悪は310ms」と言えます。アラートの条件は、こうした文から生まれます。