ガベージコレクションのトレース

このガイドでは、ガベージコレクションのトレースの基本について説明します。

このガイドを最後まで読むと、次のことができるようになります。

Node.js アプリケーションでトレースを有効にする
トレースを解釈する
Node.js アプリケーションの潜在的なメモリの問題を特定する

ガベージコレクターの仕組みについては学ぶべきことがたくさんありますが、1 つだけ覚えておくべきことは、GC が実行されているときはコードが実行されていないということです。

ガベージコレクションがどれくらいの頻度と時間実行されるか、そしてその結果を知りたいと思うかもしれません。

セットアップ

このガイドでは、次のスクリプトを使用します。

// script.mjs

import os from 'node:os';

let len = 1_000_000;
const entries = new Set();

function addEntry() {
  const entry = {
    timestamp: Date.now(),
    memory: os.freemem(),
    totalMemory: os.totalmem(),
    uptime: os.uptime(),
  };

  entries.add(entry);
}

function summary() {
  console.log(`Total: ${entries.size} entries`);
}

// execution
(() => {
  while (len > 0) {
    addEntry();
    process.stdout.write(`~~> ${len} entries to record\r`);
    len--;
  }

  summary();
})();

JavaScriptクリップボードにコピー

リークがここで明らかであっても、実際のアプリケーションのコンテキストでリークの原因を見つけるのは面倒な場合があります。

ガベージコレクションのトレースを実行する

--trace-gc フラグを使用すると、プロセスのコンソール出力にガベージコレクションのトレースが表示されます。

$ node --trace-gc script.mjs

Bashクリップボードにコピー

注: この演習のソースコードは、Node.js Diagnostics リポジトリにあります。

次のような出力が得られます。

[39067:0x158008000]     2297 ms: Scavenge 117.5 (135.8) -> 102.2 (135.8) MB, 0.8 / 0.0 ms  (average mu = 0.994, current mu = 0.994) allocation failure
[39067:0x158008000]     2375 ms: Scavenge 120.0 (138.3) -> 104.7 (138.3) MB, 0.9 / 0.0 ms  (average mu = 0.994, current mu = 0.994) allocation failure
[39067:0x158008000]     2453 ms: Scavenge 122.4 (140.8) -> 107.1 (140.8) MB, 0.7 / 0.0 ms  (average mu = 0.994, current mu = 0.994) allocation failure
[39067:0x158008000]     2531 ms: Scavenge 124.9 (143.3) -> 109.6 (143.3) MB, 0.7 / 0.0 ms  (average mu = 0.994, current mu = 0.994) allocation failure
[39067:0x158008000]     2610 ms: Scavenge 127.1 (145.5) -> 111.8 (145.5) MB, 0.7 / 0.0 ms  (average mu = 0.994, current mu = 0.994) allocation failure
[39067:0x158008000]     2688 ms: Scavenge 129.6 (148.0) -> 114.2 (148.0) MB, 0.8 / 0.0 ms  (average mu = 0.994, current mu = 0.994) allocation failure
[39067:0x158008000]     2766 ms: Scavenge 132.0 (150.5) -> 116.7 (150.5) MB, 1.1 / 0.0 ms  (average mu = 0.994, current mu = 0.994) allocation failure
Total: 1000000 entries

Bashクリップボードにコピー

読みにくいですか？いくつかの概念を見直し、--trace-gc フラグの出力を説明しましょう。

`--trace-gc` を使用したトレースの確認

--trace-gc (または --trace_gc、どちらでも可) フラグは、すべてのガベージコレクションイベントをコンソールに出力します。各行の構成は次のように説明できます。

[13973:0x110008000]       44 ms: Scavenge 2.4 (3.2) -> 2.0 (4.2) MB, 0.5 / 0.0 ms  (average mu = 1.000, current mu = 1.000) allocation failure

Bashクリップボードにコピー

トークン値	解釈
13973	実行中のプロセスの PID
0x110008000	分離 (JS ヒープインスタンス)
44 ms	プロセス開始からの経過時間 (ミリ秒)
スカベンジ	GC の種類 / フェーズ
2.4	GC 前に使用されたヒープ (MB)
(3.2)	GC 前の合計ヒープ (MB)
2.0	GC 後に使用されたヒープ (MB)
(4.2)	GC 後の合計ヒープ (MB)
0.5 / 0.0 ms (平均 mu = 1.000、現在の mu = 1.000)	GC に費やされた時間 (ミリ秒)
割り当てエラー	GC の理由

ここでは 2 つのイベントにのみ焦点を当てます。

スカベンジ
マークスイープ

ヒープは *スペース* に分割されます。これらのうち、「新しい」スペースと呼ばれるスペースと「古い」スペースと呼ばれるスペースがあります。

👉 実際には、ヒープ構造は少し異なりますが、この記事ではよりシンプルなバージョンに固執します。詳細については、Orinoco に関するPeter Marshall の講演をご覧ください。

スカベンジ

スカベンジは、新しいスペースでガベージコレクションを実行するアルゴリズムの名前です。新しいスペースは、オブジェクトが作成される場所です。新しいスペースは、ガベージコレクションが高速に実行されるように小さく設計されています。

スカベンジのシナリオを想像してみましょう。

A、B、C、D を割り当てました。
```
| A | B | C | D | <unallocated> |
```
Bashクリップボードにコピー
E を割り当てたい
スペースが足りず、メモリが不足している
その後、(ガベージ) コレクションがトリガーされる
デッドオブジェクトが収集される
生きているオブジェクトは残る
B と D がデッドだったと仮定する
```
| A | C | <unallocated> |
```
Bashクリップボードにコピー
これで E を割り当てることができる
```
| A | C | E | <unallocated> |
```
Bashクリップボードにコピー

v8 は、2 回のスカベンジオペレーション後にガベージコレクションされないオブジェクトを古いスペースに昇格させます。

👉 完全なスカベンジシナリオ

マークスイープ

マークスイープは、古いスペースからオブジェクトを収集するために使用されます。古いスペースは、新しいスペースで生き残ったオブジェクトが存在する場所です。

このアルゴリズムは 2 つのフェーズで構成されています。

**マーク**: まだ生きているオブジェクトを黒、他のオブジェクトを白とマークします。
**スイープ**: 白いオブジェクトをスキャンし、それらを空きスペースに変換します。

👉 実際には、マークとスイープの手順はもう少し複雑です。詳細については、このドキュメントをお読みください。

`--trace-gc` の動作

メモリリーク

前の端末ウィンドウにすばやく戻ると、コンソールに多くの `Mark-sweep` イベントが表示されます。また、イベント後に収集されたメモリの量がごくわずかであることもわかります。

これでガベージコレクションの専門家になりました！何が推測できるでしょうか？

おそらくメモリリークが発生しています！しかし、どうやってそれを確信できるでしょうか？(注意: この例では非常に明白ですが、実際のアプリケーションではどうでしょうか？)

しかし、どのようにコンテキストを見つけることができるでしょうか？

不正な割り当てのコンテキストを取得する方法

古いスペースが sürekli olarak arttığını varsayalım.
--max-old-space-size を減らして、合計ヒープを制限に近づけます。
メモリ不足になるまでプログラムを実行します。
生成されたログは、失敗したコンテキストを示しています。
OOM に達した場合は、ヒープサイズを約 10% 増やして数回繰り返します。同じパターンが観察された場合、メモリリークを示しています。
OOM がない場合は、ヒープサイズをその値に固定します。パックされたヒープは、メモリフットプリントと計算レイテンシを削減します。

たとえば、次のコマンドで script.mjs を実行してみてください。

node --trace-gc --max-old-space-size=50 script.mjs

Bashクリップボードにコピー

OOM が発生するはずです。

[...]
<--- Last few GCs --->
[40928:0x148008000]      509 ms: Mark-sweep 46.8 (65.8) -> 40.6 (77.3) MB, 6.4 / 0.0 ms  (+ 1.4 ms in 11 steps since start of marking, biggest step 0.2 ms, walltime since start of marking 24 ms) (average mu = 0.977, current mu = 0.977) finalize incrementa[40928:0x148008000]      768 ms: Mark-sweep 56.3 (77.3) -> 47.1 (83.0) MB, 35.9 / 0.0 ms  (average mu = 0.927, current mu = 0.861) allocation failure scavenge might not succeed
<--- JS stacktrace --->
FATAL ERROR: Reached heap limit Allocation failed - JavaScript heap out of memory [...]

Bashクリップボードにコピー

今度は 100MB で試してみてください。

node --trace-gc --max-old-space-size=100 script.mjs

Bashクリップボードにコピー

同様のことが発生するはずです。唯一の違いは、最後の GC トレースに含まれるヒープサイズが大きくなることです。

<--- Last few GCs --->
[40977:0x128008000]     2066 ms: Mark-sweep (reduce) 99.6 (102.5) -> 99.6 (102.5) MB, 46.7 / 0.0 ms  (+ 0.0 ms in 0 steps since start of marking, biggest step 0.0 ms, walltime since start of marking 47 ms) (average mu = 0.154, current mu = 0.155) allocati[40977:0x128008000]     2123 ms: Mark-sweep (reduce) 99.6 (102.5) -> 99.6 (102.5) MB, 47.7 / 0.0 ms  (+ 0.0 ms in 0 steps since start of marking, biggest step 0.0 ms, walltime since start of marking 48 ms) (average mu = 0.165, current mu = 0.175) allocati

Bashクリップボードにコピー

注: 実際のアプリケーションのコンテキストでは、コード内でリークしたオブジェクトを見つけるのは面倒な場合があります。ヒープスナップショットは、それを見つけるのに役立ちます。ヒープスナップショット専用のガイドをご覧ください。

低速化

ガベージコレクションが多すぎるかどうか、またはオーバーヘッドが発生しているかどうかをどのようにアサートしますか？

トレースデータ、特に連続したコレクション間の時間を見直します。
トレースデータ、特に GC に費やされた時間を見直します。
2 つの GC 間の時間が GC に費やされた時間よりも短い場合、アプリケーションは深刻な不足状態にあります。
2 つの GCS 間の時間と GC に費やされた時間が非常に長い場合、アプリケーションはより小さなヒープを使用できる可能性があります。
2 つの GCS 間の時間が GC に費やされた時間よりもはるかに長い場合、アプリケーションは比較的健全です。

リークの修正

リークを修正しましょう。オブジェクトを使用してエントリを格納する代わりに、ファイルを使用できます。

スクリプトを少し変更しましょう。

// script-fix.mjs
import os from 'node:os';
import fs from 'node:fs/promises';

let len = 1_000_000;
const fileName = `entries-${Date.now()}`;

async function addEntry() {
  const entry = {
    timestamp: Date.now(),
    memory: os.freemem(),
    totalMemory: os.totalmem(),
    uptime: os.uptime(),
  };
  await fs.appendFile(fileName, JSON.stringify(entry) + '\n');
}

async function summary() {
  const stats = await fs.lstat(fileName);
  console.log(`File size ${stats.size} bytes`);
}

// execution
(async () => {
  await fs.writeFile(fileName, '----START---\n');
  while (len > 0) {
    await addEntry();
    process.stdout.write(`~~> ${len} entries to record\r`);
    len--;
  }

  await summary();
})();

JavaScriptクリップボードにコピー

Set を使用してデータを格納することは決して悪い習慣ではありません。プログラムのメモリフットプリントに注意する必要があります。

注: この演習のソースコードは、Node.js Diagnostics リポジトリにあります。

それでは、このスクリプトを実行しましょう。

node --trace-gc script-fix.mjs

次の 2 つの点に注意してください。

Mark-sweep イベントの発生頻度が低い
最初のスクリプトでは 130MB 以上だったのに対し、メモリフットプリントは 25MB を超えない。

新しいバージョンは最初のバージョンよりもメモリへの負荷が少ないため、これは非常に理にかなっています。

**要点**: このスクリプトの改善についてどう思いますか？おそらく、スクリプトの新しいバージョンは遅いことに気付くでしょう。Set を再び使用し、メモリが特定のサイズに達したときにのみその内容をファイルに書き込むとどうでしょうか？

getheapstatistics API が役立つ場合があります。

ボーナス: プログラムでガベージコレクションをトレースする

`v8` モジュールの使用

プロセス全体のライフタイムからのトレースを取得することは避けた方が良い場合があります。その場合は、プロセス内からフラグを設定します。`v8` モジュールは、フラグを動的に設定するための API を公開しています。

import v8 from 'v8';

// enabling trace-gc
v8.setFlagsFromString('--trace-gc');

// disabling trace-gc
v8.setFlagsFromString('--notrace-gc');

JavaScriptクリップボードにコピー

パフォーマンスフックの使用

Node.js では、パフォーマンスフックを使用してガベージコレクションをトレースできます。

const { PerformanceObserver } = require('node:perf_hooks');

// Create a performance observer
const obs = new PerformanceObserver(list => {
  const entry = list.getEntries()[0];
  /*
  The entry is an instance of PerformanceEntry containing
  metrics of a single garbage collection event.
  For example:
  PerformanceEntry {
    name: 'gc',
    entryType: 'gc',
    startTime: 2820.567669,
    duration: 1.315709,
    kind: 1
  }
  */
});

// Subscribe to notifications of GCs
obs.observe({ entryTypes: ['gc'] });

// Stop subscription
obs.disconnect();

JavaScriptクリップボードにコピー

パフォーマンスフックを使用したトレースの調査

PerformanceObserver のコールバックから、GC 統計を PerformanceEntry として取得できます。

例：

PerformanceEntry {
  name: 'gc',
  entryType: 'gc',
  startTime: 2820.567669,
  duration: 1.315709,
  kind: 1
}

TypeScriptクリップボードにコピー

プロパティ	解釈
name	パフォーマンスエントリの名称。
entryType	パフォーマンスエントリのタイプ。
startTime	高精度ミリ秒タイムスタンプで、パフォーマンスエントリの開始時刻を示します。
duration	このエントリに経過したミリ秒の合計数。
kind	発生したガベージコレクション操作のタイプ。
flags	GC に関する追加情報。

詳細については、パフォーマンスフックに関するドキュメントを参照してください。

次へNode.js入門