The Node.js bug that's invisible to your monitoring

ヘルスチェックではすべて正常と表示されています。応答時間はわずか1ミリ秒。しかし、トラフィックが増加すると、突然p99レイテンシが400msに跳ね上がります。ダッシュボードを確認しても、すべては「正常（グリーン）」を示しています。

CPU使用率は適度です。イベントループのラグも平坦です。メモリも健全です。APMはリクエストの遅延を示していますが、その原因については何も教えてくれません。遅いデータベースコールも、エラーもありません。

時間はlibuvスレッドプールで消費されています。

標準的なNode.jsのオブザーバビリティ（可観測性）は、イベントループに焦点を当てています。しかし、スレッドプールは別のキューであり、監視の及ばない場所に存在します。

Node.jsはイベントループ上でJavaScriptを実行します。重いタスクはlibuvスレッドプールに送られます。これには以下が含まれます：

  • ファイルシステム操作 (fs.readFile, fs.writeFile)。
  • 暗号化タスク (bcrypt, scrypt, pbkdf2)。
  • 圧縮 (zlib gzip, deflate)。
  • DNSルックアップ (dns.lookup)。

スレッドプールのデフォルトはわずか4スレッドです。これは、マシンのCPUコア数に関わらず同様です。

4スレッドでは不十分です。スレッドプールが機能不全に陥る3つのパターンを紹介します：

  1. ログイン時のBcrypt。単一のbcryptハッシュ計算に250msかかることがあります。もし4人が同時にログインすると、すべてのスロットが埋まってしまいます。5人目のユーザーはキューで待機することになり、開始するだけで250msを費やすことになります。その結果、レイテンシは倍増します。

  2. 大規模なgzip操作。大きなレスポンスを圧縮すると、スレッドプールのスロットが占有されます。もし4つのリクエストが同時にこれを行うと、他のすべてのタスクが待機状態になります。DNSルックアップやファイルの読み込みも列に並んで止まってしまいます。

  3. DNSルックアップ。ほとんどのNode.jsアプリはdns.lookupを使用しています。これはブロッキングのシステムコールを使用するため、タスクはスレッドプールに送られます。ネットワークに一時的な問題が発生すると、これらのルックアップがプール全体を停滞させます。

プール内のキューで停滞しているリクエストは、目に見えません。CPUを使用しておらず、JavaScriptを実行しているわけでもありません。ただ「停車」しているだけなのです。

見つけ方：

負荷がかかったときにp99レイテンシが上昇する一方で、イベントループのラグが平坦なままであれば、スレッドプールを確認してください。

最速のテスト方法：UV_THREADPOOL_SIZEを増やします。環境変数で64に設定して再起動してください。もしレイテンシが低下すれば、原因を特定できたことになります。

正しい修正方法：

  • bcryptのような重い暗号化処理にはworker_threadsを使用します。これにより、libuvプールを回避できます。
  • dns.lookupの代わりにdns.resolveを使用します。これは真の非同期リゾルバーです。
  • zlib処理にはストリームを使用して、スロットをより早く解放するようにします。
  • メインのリクエストパスでの重いファイルシステム操作を避けます。

ユーザーが待っている間に、緑色のダッシュボードを眺め続けるのはやめましょう。

Source: https://dev.to/r9v/the-nodejs-bug-thats-invisible-to-your-monitoring-oo8