1720478011
2024-07-08 20:52:01
以下は、Node.js イベント ループ ラグによって引き起こされた、Node.js アプリケーションのさまざまな信頼性とパフォーマンスの問題をどのように発見し、修正したかを説明するものです。
発見
6 月 20 日木曜日の午後 11 時頃（UTC 午後 10 時）に、ダッシュボード/API インスタンスの一部がクラッシュし始めたため、Trigger.dev クラウドを動かす本番環境サービスに問題が発生したという警告を受けました。
AWS の運用ダッシュボードにアクセスしてみると、インスタンスの CPU 使用率が非常に高く、増加していることがわかりました。
クラッシュしたインスタンスのログを調べたところ、Prisma トランザクション タイムアウトなどのさまざまなエラーが見つかりました。
_10
Error: Invalid `prisma.taskAttempt.create()` invocation:Transaction API error: Transaction already closed: A query cannot be executed on an expired transaction. The timeout for this transaction was 5000 ms, however 6385 ms passed since the start of the transaction.
続いて Prisma から、schema.prisma ファイルが見つからず、例外がキャッチされなかったためプロセスが終了したというメッセージが表示されます。
_10
Error: Prisma Client is unable to find the Prisma schema file for this project. Please make sure the file exists at /app/prisma/schema.prisma.
プライマリデータベースの負荷は一貫して10%未満で、接続数も正常だったため、これらのエラーに困惑しました。また、すでに閉じられている接続にWebSocketメッセージを送信するなど、クラッシュを引き起こす他のエラーも確認されました（ 例外をスローする）
同時に、ネットワーク トラフィックが急増していることに気づきました。API へのリクエストがそれに応じて増加していないため、これは奇妙なことでした。
現地時間の午前 1 時過ぎに、問題を解決できると期待していたいくつかのものをデプロイしました (ネタバレ: 解決しませんでした)。デプロイが完了するのを待っている間に、メトリクス エンドポイントにアクセスし、何か手がかりが見つかるのではないかと期待していました。実際に何かを見つけました。
デプロイが完了し、CPU 使用率が下がり、クラッシュが止まったので、問題が解決したと期待して就寝しました。
問題は再び
翌朝、同じ問題に気づきました。CPU 使用率は再び高くなり、データベースは安定し、ネットワーク トラフィックは増加しました。振り出しに戻ってしまいました。
ネットワークトラフィックの急増の背後にあるものをもっとよく理解できれば、問題の根本原因を見つけられるだろうという予感がありました。AWS Application Load Balancerのログにアクセスできたので、それを照会する機能を設定しました。 アテナ まず、最も使用されている IP を調べました。
_13
COUNT(*) as request_count,
_13
sum(received_bytes) / 1024 / 1024 as rx_total_mb,
_13
sum(sent_bytes) / 1024 / 1024 as tx_total_mb
かなり明確な勝者が出ました。
これは、1 つの IP アドレスが 1 日で 21 GB のデータを使用することを意味します。この IP がどのパスにアクセスして高いネットワーク トラフィックを引き起こしているかを確認するために、別のクエリを作成しました。
_21
COUNT(*) as request_count,
_21
min(time) as first_request,
_21
max(time) as last_request,
_21
sum(received_bytes) / 1024 / 1024 as rx_total_mb,
_21
sum(sent_bytes) / 1024 / 1024 as tx_total_mb,
_21
and client_ip = '93.xxx.xxx.155'
トラフィックのほとんどは、いくつかの異なるパスから来ていましたが、それらはすべて v3 実行トレース ビューを指していました (これは単なる例です)。
しかし、上記のクエリでは、それぞれ数千のリクエストを含むいくつかのパスが表示されました。データベースを詳しく調べたところ、これらの実行にはそれぞれ 20,000 以上のログがあり、トレース ビューにはページ区切りがないことがわかりました。また、新しいログが入るたびに、最大で 1 秒に 1 回、トレース ビューを「ライブ リロード」します。
つまり、誰かが v3 の実行をトリガーし、トレース ビューを表示すると、20,000 を超えるログが入り、ページ全体が毎秒更新されていました。これにより、ネットワーク トラフィックが増大していましたが、CPU 使用率が高くなる原因は説明されていません。
根本原因を解明するための次のステップは、基礎となるコードに追加のテレメトリを組み込むことでした。幸いなことに、アプリケーションにはすでにOpenTelemetryが設定されており、トレースを送信します。 ベースライムコードにスパンを追加した後、次のようなトレースが表示されるようになりました。
上のトレースを見るとわかるように、かなりの時間が createSpans 約 30 秒間調べた後、問題が何であるかがかなり明確になりました。
_10
// This isn't the actual code, but a simplified version
_10
for (const log of logs) {
_10
// remember, 20k+ logs
_10
const parentSpan = logs.find((l) => log.parentId === l.id);
はい、これはネストされたループです。20,000 以上のログを反復処理し、各ログについて、すべてのログを再度反復処理して親ログを見つけていました (20k * 20k = 400m)。Big O 表記では、これは O(n^2) ですが、あまり良くありません (本当に悪いです)。
ID 別にログのマップを作成し、ログを 1 回反復処理してスパンを作成することで、この問題を修正しました。この修正をすぐに展開し (ログが 1000 未満の場合にトレース ビューのライブ リロードを制限するとともに)、CPU 使用率が低下し、ネットワーク トラフィックが減少し、クラッシュが停止しました (今のところ)。
この 1 つの問題が修正されたので、前夜に発見したイベント ループ ラグに再び注意を向けました。この問題の 1 つのインスタンスは解決しましたが、これが問題の原因となっている唯一の場所ではないと感じていました。
残りのイベント ループ ラグの問題をどのように発見して修正したかを詳しく説明する前に、少し立ち止まって、イベント ループ ラグとは何かを説明しましょう。
イベントループラグ: 入門
Node.js には操作スレッドが少数しかなく、イベント ループはメイン スレッドに属しています。つまり、入ってくるすべてのリクエストはメイン スレッドで処理されます。
これにより、Node.jsサービスは、より限られたメモリとリソースの消費で実行できるようになります。 各クライアントがメインスレッドで行っている作業は小さい。
このように、Node.js は、バリスタが 1 人いる近所のコーヒー ショップに少し似ています。ダブル ベンティ ソイ クアッド ショット ウィズ フォームを注文する人がいない限り、コーヒー ショップはすぐに全員にサービスを提供できます。しかし、バリスタが 1 人いると、全体のプロセスが遅くなり、列に並んでいる多くの顧客に不満を抱かせる可能性があります。
では、これをどのようにスケールできるのでしょうか? 実は、Node.js は一部の作業を他のスレッドにオフロードします。
- ファイルの読み取りと書き込み（libuv）はワーカースレッドで行われます
- DNSルックアップ
- IO操作（データベースクエリなど）はワーカースレッドで実行される
- CryptoとzlibはCPUを大量に消費しますが、ワーカースレッドにオフロードされます。
この設定の優れた点は、これを活用するために何もする必要がないことです。Node.js は、可能な場合は自動的に作業をワーカー スレッドにオフロードします。
アプリケーション開発者であるあなたに Node.js が要求するのは、メインスレッドの作業をクライアント間で公平に分散することです。そうしないと、イベント ループの遅延が発生し、コーヒーを待つ怒ったクライアントの長い列ができてしまいます。
幸いなことに、Node.jsチームはイベントループの遅延を回避する方法についての非常に包括的なガイドを公開しており、以下で見つけることができます。 ここ。
イベントループの遅延の監視
ネストされたループの問題に対する修正を展開した後、イベント ループの遅延がどのくらいの頻度で発生しているかをより正確に把握したいと考えました。イベント ループが 100 ミリ秒以上ブロックされた場合に OpenTelemetry でスパンを生成するイベント ループ モニターをアプリケーションに追加しました。
_81
import { createHook } from "node:async_hooks";
_81
import { tracer } from "/blog/event-loop-lag/v3/tracer.server";
_81
const THRESHOLD_NS = 1e8; // 100ms
_81
const cache = new Map();
_81
triggerAsyncId: number,
_81
function destroy(asyncId: number) {
_81
cache.delete(asyncId);
_81
function before(asyncId: number) {
_81
const cached = cache.get(asyncId);
_81
start: process.hrtime(),
_81
function after(asyncId: number) {
_81
const cached = cache.get(asyncId);
_81
cache.delete(asyncId);
_81
const diff = process.hrtime(cached.start);
_81
const diffNs = diff[0] * 1e9 + diff[1];
_81
if (diffNs > THRESHOLD_NS) {
_81
const time = diffNs / 1e6; // in ms
_81
const newSpan = tracer.startSpan("event-loop-blocked", {
_81
startTime: new Date(new Date().getTime() - time),
_81
asyncType: cached.type,
_81
label: "EventLoopMonitor",
_81
export const eventLoopMonitor = singleton("eventLoopMonitor", () => {
_81
const hook = createHook({ init, before, after, destroy });
_81
console.log("🥸 Initializing event loop monitor");
_81
console.log("🥸 Disabling event loop monitor");
上記のコードは node:async_hooks 間の時間を計測し記録する before そして after フック。2つの間の継続時間が100msを超える場合は、OpenTelemetryでスパンを作成し、 startTime その時までに before フックが実行されました。
金曜日の午後にモニターを展開し、結果を待ちました。現地時間の午後 10 時頃、かなり長い期間のスパンが作成され始めたのがわかりました。
イベントループの遅延モグラ叩き
24日月曜日の朝から、私たちは PR イベント ループの遅延問題をできるだけ多く修正しました。次の修正を加えた PR を 27 日木曜日の午前 10 時 (UTC) 頃に送信してデプロイしました。
- トレース ビューに 25,000 ログの制限を追加しました (222,000 ログの実行を検出した後)。ユーザーが必要に応じてすべてのログをダウンロードできるように、「すべてのログをダウンロード」ボタンを追加しました。
- ユーザーが 8,000 以上のスケジュールを持っている場合に 15 秒の遅延が発生したため、v2 スケジュール トリガー リストにページ区切りを追加しました。
- v2 タスクへの入力に 3MB のハード制限を追加しました (制限がまったくないことに気付いた後)。これは v2 タスクの出力制限と一致します。
- 重要なのは、v2タスクの入力と出力のサイズを計算する方法を変更したことです。以前は、
Buffer.byteLengthリクエスト本体のJSONを解析した後、イベントループが入力と出力のサイズを計算する際にブロックされる原因となっていました。現在は、JSONを解析する前に、Content-Lengthリクエストのヘッダー。 - Zod を使用して、受信した JSON リクエスト本文を解析し、v2 タスクの入力と出力のキーを削除して個別に処理します。
これらの修正を展開した後、イベント ループ モニターによって作成されるスパンの数が大幅に減少しました。
1 秒を超えるイベント ループ ラグが検出された場合、通知するアラートが設定されているため、発生する新しい問題を検出して修正できます。
次のステップとポイント
イベント ループの遅延問題のほとんどは修正されましたが、この分野では、特に v3 のタスクのペイロードと出力のサイズに関して、まだ取り組むべき作業が残っています。v3 では、512 KB を超えるペイロード/出力をデータベースに保存せず、代わりにオブジェクト ストア (Cloudflare R2) に保存するため、すでにかなり大きなペイロードと出力をサポートしています。
ただし、v3 ペイロードは引き続きメイン スレッドで解析されますが、今後のアップデートでは、これを改善するために次の 2 つのことを実行する予定です。
- 他のタスク内でトリガーされるタスクについては、大きなペイロードをオブジェクト ストアにアップロードし、タスクをトリガーするときにペイロードへの参照を渡します。これにより、サービスのメイン スレッドでペイロードを解析する必要がなくなります。
- クライアントサーバーからトリガーされたタスクの場合、完全なペイロードがリクエスト本体で送信されるため、ペイロードをオブジェクトストアにストリーミングします。
stream-json(私たちはすでにこの機能のプロトタイプを構築しています)。
さらに重要なことは、多数のクライアントを処理できる信頼性の高い Node.js サービスを本番環境で実行するために必要なことを、より深く理解できるようになったことです。今後は、イベント ループの遅延を回避するために、コードをより慎重に設計していきます。
補足: サーバーレスとイベントループの遅延
Trigger.dev は、長期間存続する Node.js プロセスとして実装されています。上記のように、単一のクライアントが他のすべてのクライアントのイベント ループをブロックできないようにするために、追加の作業が必要になります。これは、長期間存続する Node.js プロセスでよく見られる問題であり、サーバーレスが人気を博している理由の 1 つです。
しかし、サーバーレスは万能薬ではありません。サーバーレス関数は短命ですが、単一のスレッドで実行され、イベント ループ ラグが発生する可能性があります。これは、サーバーレス関数を使用して多数のクライアントを処理する場合や、関数内で多くの同期作業を実行する場合に特に当てはまります。
リクエストのレイテンシを低く抑えるために、関数インスタンスは起動後一定期間ウォーム状態に保たれます（コールドブートと呼ばれます）。つまり、このイベントループの遅延問題は、より多くのインスタンスを実行することでいくらか軽減されますが、サーバーレスNode.jsアプリケーションを構築する際には注意が必要です。この問題の詳細については、こちらをご覧ください。 ここ。
バックグラウンドジョブ
長時間実行される Node.js サービスを実行している場合、注意する必要があるイベント ループ ラグの原因はリクエストだけではありません。同じ Node.js プロセス内で長時間実行されるタスクやキューに入れられたタスクをオフロードすると、イベント ループ ラグが発生する可能性があり、リクエストが遅くなり、今回経験したような問題が発生します。
これは、バックグラウンド ジョブにサーバーレスを使用するパターンが非常に人気がある理由の 1 つです。バックグラウンド ジョブを別のプロセスで実行することで、メイン サービスでのイベント ループの遅延の問題を回避し、変化するワークロードに対応するためにスケールアップおよびスケールダウンできます。サーバーレスは最適なソリューションですが、イベント ループの遅延とタイムアウトを回避するために慎重な設計が必要です。
トリガー.dev v3 は開発者プレビュー版で、両方の長所を組み合わせたアプローチを採用しています。バックグラウンドタスクのコードは、タイムアウトを気にすることなく、メインサービスや他のサービスから完全に分離された別のプロセスで展開および実行されます。試してみたい場合は、 順番待ちリストに登録する。
#Node.js #イベント #ループの遅延を抑制した方法 #詳細