Claude Codeでevent loop遅延を測り、ブロッキング処理を探す

Nodeのサーバーが「普段は速いのに、たまに全リクエストが止まる」ときは、同期処理がイベントループを占有していることが多いです。平均応答時間では見えず、遅延の最大値にだけ現れます。

この記事では、perf_hooks の monitorEventLoopDelay で遅延を数字にし、その数字をClaude Codeに渡して原因の処理を絞ります。直した結果は同じ計測で比べます。サンプルは手元のNode.js v20.18.0で実際に動かした出力です。

イベントループ遅延は何を測る指標か

イベントループ遅延は、「次のタイマーやI/O処理を始めたいのに、前の処理が終わらず待たされた時間」です。同期処理が10ミリ秒かかれば、その間に届いたリクエストはすべて10ミリ秒以上待ちます。

関数ごとの所要時間を見るプロファイラーとは見る場所が違います。遅延は「症状」で、プロファイルは「犯人探し」です。

後者の絞り込みはcpuprofileの解析手順にまとめてあります。本記事は前段として、固まっている事実を数字で示す側を扱います。

monitorEventLoopDelayでヒストグラムを取る

monitorEventLoopDelay はイベントループ遅延を記録するヒストグラムを返します。値の単位はナノ秒です。enable() で記録を始め、min / max / mean / percentile(n) で読み出し、reset() で窓を切り替えます。

検証用に、/report へのアクセスで15万行を生成して並べ替える同期処理を持つサーバーを用意しました。3秒ごとに、直近3秒分の分布をJSONで1行出します。

const http = require('node:http');
const { monitorEventLoopDelay } = require('node:perf_hooks');
 
const h = monitorEventLoopDelay({ resolution: 10 });
h.enable();
 
function buildReport(n) {
  const rows = [];
  for (let i = 0; i < n; i++) rows.push({ id: i, key: 'k' + ((i * 7919) % n) });
  rows.sort((a, b) => a.key.localeCompare(b.key));
  return JSON.stringify(rows).length;
}
 
http.createServer((req, res) => {
  if (req.url === '/report') return res.end(String(buildReport(150000)));
  res.end('ok');
}).listen(3099);
 
const ms = (v) => Math.round((v / 1e6) * 10) / 10;
setInterval(() => {
  console.log(JSON.stringify({ p50: ms(h.percentile(50)), p99: ms(h.percentile(99)), max: ms(h.max) }));
  h.reset();
}, 3000).unref();

最初の窓は / だけに数回アクセスし、次の窓で /report を2回呼びました。出力は次のとおりです。

{"p50":12,"p99":13.1,"max":13.6}
{"p50":12,"p99":14,"max":119.2}

/report を呼んだ窓だけ、max が119.2msに跳ねました。ところが p99 は14msのままで、p50 はどちらも12msです。ヒストグラムの全サンプルのうち、固まった回はごく一部だからです。

平均や中央値だけを監視すると、この固まりは見えません。見るべき列は max と、サンプル数に応じた高めのパーセンタイルです。

p50 が12msと、遅延ゼロでも10msを超えて見える点にも注意が要ります。間隔ベースの計測では、各サンプルに resolution(既定10ms)分が含まれる仕様だからです。絶対値ではなく、同じ設定の前後比較として読みます。

Claude Codeに遅延の数字と「止まっている処理」を渡す

ヒストグラムは症状を示すだけで、犯人の関数までは教えません。次の2点を揃えて渡すと、Claude Codeが原因を絞りやすくなります。

• 遅延の窓ごとの出力(上の3行程度)と、跳ねた時刻に呼ばれたエンドポイント
• --cpu-prof で取った上位関数の表

プロファイルは、サーバーを --cpu-prof 付きで起動して同じ負荷をかけるだけで取れます。

node --cpu-prof --cpu-prof-dir=./prof server.js

上位関数の抜き方は先の記事のjqスクリプトをそのまま使えます。渡し方は非対話モードの claude -p を使います。標準入力にパイプでデータを渡せますが、上限は10MBです。超えるとエラーで止まるため、生のプロファイルではなく絞った表を渡します。

{ cat el-histogram.log; jq -r -f top.jq prof/*.cpuprofile; } | claude -p \
  "1つ目はイベントループ遅延(ms)の窓ごとの出力、2つ目はcpuprofileの自己時間上位です。
maxが跳ねた窓で同期的にCPUを使っている関数を特定し、
worker_threadsに移せる処理か、分割で足りる処理かを分けて答えてください。
コードはまだ書き換えないでください"

「まだ書き換えない」と書くのは、診断と修正を分けるためです。診断が合っているかを人が見てから、修正を頼みます。

返答は例えば、buildReport 内の sort の比較関数が自己時間の大半を占める、という形になります。この返答は依頼の仕方を示す作例で、実際の出力ではありません。数字は手元の検証の値です。

worker_threadsへ逃がして遅延を比べる

原因が純粋なCPU処理なら、worker_threads に移すのが標準的な逃がし方です。Nodeの公式ドキュメントも、Workersは「CPUを多く使うJavaScript処理に有効で、I/Oが多い処理にはあまり効かない」と説明しています。I/O待ちが原因なら、ワーカーに移しても遅延は減りません。

buildReport をワーカー側のファイルに移し、サーバーは結果だけを受け取ります。

// report-worker.js
const { parentPort, workerData } = require('node:worker_threads');
const n = workerData.n;
const rows = [];
for (let i = 0; i < n; i++) rows.push({ id: i, key: 'k' + ((i * 7919) % n) });
rows.sort((a, b) => a.key.localeCompare(b.key));
parentPort.postMessage(JSON.stringify(rows).length);

// server.js 側
const { Worker } = require('node:worker_threads');
function runInWorker(n) {
  return new Promise((resolve, reject) => {
    const w = new Worker(__dirname + '/report-worker.js', { workerData: { n } });
    w.once('message', resolve);
    w.once('error', reject);
  });
}
// ハンドラー
if (req.url === '/report') return runInWorker(150000).then((len) => res.end(String(len)));

同じ手順で計測した結果は次のとおりです。

最大遅延は100ms超から、通常の揺れの範囲まで下がりました。

/report 自身の応答時間も、curl -s -o /dev/null -w '%{time_total}\n' で3回ずつ測り直しました。同期実行は0.105〜0.143秒、ワーカーは0.139〜0.146秒で、ワーカー側が同程度かやや遅い結果です。ワーカーの起動とデータの受け渡しが加わるためと考えられます。ほかのリクエストを止めない代わりに、呼んだ本人の待ち時間は縮みません。

リクエストごとにワーカーを立てる書き方は、検証のための最小形です。呼び出しが多いサービスでは、ワーカーを使い回すプールを使う設計にします。プールでの値は、この比較に含まれていません。

遅延と稼働率(ELU)の使い分け

performance.eventLoopUtilization() は、イベントループがどれだけ埋まっていたかを返します。idle と active の累積時間(ミリ秒)に、比率の utilization(0〜1)が付きます。前回の戻り値を引数に渡すと、その間の差分が返ります。ELUはCPU使用率とは別物で、ループがイベント待ち(epoll_wait)の外にいた時間の割合です。同期処理で塞がっている間は、CPUが遊んでいても utilization は高くなります。

monitorEventLoopDelay が「待たされた最大時間」を見るのに対し、ELUは「窓全体のうち何割が埋まっていたか」を見ます。同じ検証サーバーに3秒ごとの差分出力を足し、/report を3回呼びました。

const { performance } = require('node:perf_hooks');
let prev = performance.eventLoopUtilization();
setInterval(() => {
  const cur = performance.eventLoopUtilization();
  const d = performance.eventLoopUtilization(cur, prev);
  prev = cur;
  console.log(JSON.stringify({ elu: Math.round(d.utilization * 1000) / 1000 }));
}, 3000).unref();

メインスレッドで同期実行したときの窓は max が151ms、elu が0.136でした。ほかの窓の elu は0.005〜0.006です。3回分の同期処理で約0.4秒、3秒の窓の1割余りが埋まった計算になります。ワーカーに移した構成では、/report を呼んだ窓の elu は0.006で、max は19.3msでした。

使い分けは次のとおりです。短い固まりを逃さず見るなら max、サーバー全体の余裕を見るならELUです。常時監視するときは、定期的に差分を取って既存のメトリクスに送る形になります。窓ごとの elu と max を並べて送れば、「長く埋まっているのか、一瞬固まったのか」を切り分けられます。

分割で譲る方法は、一括呼び出しには効かない

ワーカーを使わずに、処理を小分けして setImmediate でループに制御を返す方法もあります。同じ buildReport を、5,000行ごとに譲る形へ書き換えて試しました。

async function buildChunked(n) {
  const rows = [];
  for (let i = 0; i < n; i++) {
    rows.push({ id: i, key: 'k' + ((i * 7919) % n) });
    if (i % 5000 === 4999) await new Promise((r) => setImmediate(r));
  }
  rows.sort((a, b) => a.key.localeCompare(b.key));
  return JSON.stringify(rows).length;
}

結果は、/report を呼んだ窓の max が132.1msで、分割前の119.2msと変わりませんでした。

{"p50":12,"p99":13.4,"max":16.6}
{"p50":12,"p99":15.3,"max":132.1}

行を作るループは分割できても、後ろの sort と JSON.stringify は1回の呼び出しで最後まで走ります。固まっていた本体はこの2つでした。分割が効くのは、for ループで自前の処理を回している場合に限られます。

この差は、Claude Codeに依頼するときの前提になります。診断の返答に「分割で足りる」とあっても、その処理の大半が組み込みの一括呼び出しなら、分割後に同じ計測を回して max が下がったかを確かめます。下がらなければ、ワーカーに戻します。

直ったかを合否で確かめる

Claude Codeに修正を任せるときは、「直ったか」を判定できるコマンドを先に用意します。公式のベストプラクティスも、合否が返るチェックを渡すと、Claudeが出力を読んで直し、再実行するループを自分で回せるようになると述べています。

遅延の場合は、負荷をかけたあとに max がしきい値を超えたら終了コード1を返すスクリプトが、そのチェックになります。

// check-el.js(抜粋)
const MAX_MS = 50;
const max = h.max / 1e6;
console.log(`event loop max: ${max.toFixed(1)}ms`);
process.exit(max > MAX_MS ? 1 : 0);

しきい値の50msは、手元の検証での通常の揺れ(約14ms以下)より十分大きく、固まりの119msより小さい値として置いた例です。自分のサービスでは、まず通常時の max を計測して決めます。

このスクリプトを npm run check:eventloop として登録し、.claude/settings.json のStopフックから呼ぶと、遅延が残る間はClaude Codeがターンを終えられません。公式のStopフックの例と同じく、終了コード2で止め、標準エラー出力がClaudeに戻ります。

{
  "hooks": {
    "Stop": [
      {
        "hooks": [
          { "type": "command", "command": "npm run check:eventloop 1>&2 || exit 2" }
        ]
      }
    ]
  }
}

公式の説明では、フックが連続で止め続けた場合は上限に達した時点でターンが終わります。負荷試験が重い場合は、常時フックにせず、依頼文で「修正後に npm run check:eventloop を実行して出力を貼る」と書く方法でも足ります。Makefileにまとめる方法は検証ループの作り方で扱っています。

つまずきやすい点

窓の切り方で数字が変わります。reset() を呼ばずに長時間動かすと、起動直後の揺れが max に残り続けます。上の例のように定期的に reset() して、窓ごとに出力します。

サンプリング方式の選択肢は、Nodeのバージョンで違います。最新のNodeのドキュメントでは、samplePerIteration がv26.5.0、lowest / highest / figures がv26.11.0で追加されたと記載されています。本記事の例はv20.18.0で動かしたため resolution だけを使っています。samplePerIteration を使うと、間隔ベースとは結果が大きく異なり、直接比較できないとドキュメントにあります。

ワーカーや分割が効かない遅延もあります。 JSON.parse のような組み込みの一括呼び出しは、前節のとおり分割しても縮みません。同期のファイル読み込みが原因なら、fs.promises の非同期APIに置き換えるのが先です。ワーカーへ渡すデータのコピーが重い場合も、効果が打ち消されます。

他の診断ツールとの関係は、使い分けです。Clinic.js Doctorは、Nodeのプロセスを起動して収集し、HTMLレポートを出す診断ツールです。GUIで全体像を眺めたいときに向きます。Claude Codeへ渡すなら、数行のテキストで出せる monitorEventLoopDelay のほうが扱いやすい。

フロントエンドの似た症状は別物です。ブラウザー側でクリック後の応答が重い場合は、サーバーのイベントループではなく、メインスレッドのイベントハンドラーが原因です。そちらはINPの改善手順が対応します。

まとめ

遅延の最大値で症状を数字にし、プロファイルで原因の関数を絞り、CPU処理ならワーカーへ移す。この3段を、同じ計測スクリプトの前後比較で閉じるのが要点です。検証では最大遅延が119.2msから14.3msに下がり、引き換えに /report の応答時間は縮まず、同程度かやや遅くなりました。

Claude Codeに任せる範囲は、診断の依頼と、合否つきの修正ループです。しきい値の決め方と、ワーカーを増やしてよい負荷かどうかは、サービスの実測で人が決めます。