Jest のメモリまわりでハマった話

こんにちは、Sansan Engineering Unit の渡邉です🦐

私たちのチームではTypeScriptで開発しており、テストはJestを用いて書いています。ある日からテストが結構な頻度で落ちてしまうように（FLAKY *1に）なっていました...。
そこで、テストがFLAKYになっている原因を深掘り調査したところ、Jestのメモリまわりについて解像度が高まったので、備忘録代わりに残します。

結論

Jestにおけるタイムアウトエラーとメモリエラー（Out Of Memory）を次のオプションを設定し、防止できました。

`jest.config.js`

  ...
  testTimeout: 30000, // タイムアウト時間を延長
  workerIdleMemoryLimit: '1024MB', // ワーカーが使用できるメモリ上限を制限
  maxWorkers: 4, // テストを並列実行しないとメインスレッドで実行されてしまい、workerIdleMemoryLimitでメモリ上限を制限できない
  ...

調査内容

環境

Node.jsとJestのバージョンは次の通りです。

Node.js: v16.20.2
Jest: 29.4.1

タイムアウトエラー

はじめに、CIのテスト実行ログを確認すると特定のテストケースでタイムアウトエラーになっていました。

thrown: "Exceeded timeout of 10000 ms for a test.
Use jest.setTimeout(newTimeout) to increase the timeout value, if this is a long-running test."

根本的な解決ではないですが、ひとまずは次のようにJestの設定を変更し、タイムアウト時間を延ばしました。

  ...
  testTimeout: 30000 // 元々は 10000 だった
  ...

jestjs.io

メモリエラー

その後、タイムアウトエラーでテストの失敗はなくなりましたが、次のようなメモリエラー（Out of Memory）が頻発するようになってしまいました。

<--- Last few GCs --->

[36:0x6072e00]   372437 ms: Mark-sweep (reduce) 2581.4 (3074.6) -> 2580.7 (3033.1) MB, 2864.5 / 0.0 ms  (average mu = 0.041, current mu = 0.025) last resort GC in old space requested
[36:0x6072e00]   375170 ms: Mark-sweep (reduce) 2580.7 (3033.1) -> 2580.5 (3023.1) MB, 2732.5 / 0.0 ms  (average mu = 0.021, current mu = 0.000) last resort GC in old space requested


<--- JS stacktrace --->

FATAL ERROR: CALL_AND_RETRY_LAST Allocation failed - JavaScript heap out of memory
 1: 0xb090e0 node::Abort() [/usr/bin/node]
 2: 0xa1b70e  [/usr/bin/node]
 3: 0xce1a20 v8::Utils::ReportOOMFailure(v8::internal::Isolate*, char const*, bool) [/usr/bin/node]
 4: 0xce1dc7 v8::internal::V8::FatalProcessOutOfMemory(v8::internal::Isolate*, char const*, bool) [/usr/bin/node]
 5: 0xe99435  [/usr/bin/node]
 6: 0xeabea8 v8::internal::Heap::AllocateRawWithRetryOrFailSlowPath(int, v8::internal::AllocationType, v8::internal::AllocationOrigin, v8::internal::AllocationAlignment) [/usr/bin/node]
 7: 0xe79c06 v8::internal::Factory::CodeBuilder::AllocateCode(bool) [/usr/bin/node]
 8: 0xe7a265 v8::internal::Factory::CodeBuilder::BuildInternal(bool) [/usr/bin/node]
 9: 0xe7ac7e v8::internal::Factory::CodeBuilder::Build() [/usr/bin/node]
10: 0x14c8dde v8::internal::RegExpMacroAssemblerX64::GetCode(v8::internal::Handle<v8::internal::String>) [/usr/bin/node]
11: 0x11b4609 v8::internal::RegExpCompiler::Assemble(v8::internal::Isolate*, v8::internal::RegExpMacroAssembler*, v8::internal::RegExpNode*, int, v8::internal::Handle<v8::internal::String>) [/usr/bin/node]
12: 0x11d2997 v8::internal::RegExpImpl::Compile(v8::internal::Isolate*, v8::internal::Zone*, v8::internal::RegExpCompileData*, v8::base::Flags<v8::internal::JSRegExp::Flag, int>, v8::internal::Handle<v8::internal::String>, v8::internal::Handle<v8::internal::String>, bool, unsigned int&) [/usr/bin/node]
13: 0x11d3140 v8::internal::RegExpImpl::CompileIrregexp(v8::internal::Isolate*, v8::internal::Handle<v8::internal::JSRegExp>, v8::internal::Handle<v8::internal::String>, bool) [/usr/bin/node]
14: 0x11d3d3e v8::internal::RegExpImpl::IrregexpPrepare(v8::internal::Isolate*, v8::internal::Handle<v8::internal::JSRegExp>, v8::internal::Handle<v8::internal::String>) [/usr/bin/node]
15: 0x11d3eb7 v8::internal::RegExpImpl::IrregexpExec(v8::internal::Isolate*, v8::internal::Handle<v8::internal::JSRegExp>, v8::internal::Handle<v8::internal::String>, int, v8::internal::Handle<v8::internal::RegExpMatchInfo>, v8::internal::RegExp::ExecQuirks) [/usr/bin/node]
16: 0x11f9088 v8::internal::Runtime_RegExpExec(int, unsigned long*, v8::internal::Isolate*) [/usr/bin/node]
17: 0x15d9e59  [/usr/bin/node]

そこで、次のようにJest実行時のオプションを追加し、テストケースごとのヒープ領域の使用量を出力するようにしました。

jest --logHeapUsage

archive.jestjs.io

すると、テストが実行されるにつれてヒープ使用量が段階的に増加していることがわかりました。

 ...
 PASS  *** (1580 MB heap size)
 PASS  *** (1720 MB heap size)
 PASS  *** (1513 MB heap size)
 PASS  *** (1609 MB heap size)
 PASS  *** (1809 MB heap size)
 ...

Jest のメモリ消費に関するバグ

どうやらこれはNode.jsの特定のバージョンで発生するJestのバグのようで、Jestワーカーが利用可能なRAMをすべて消費するという問題があるようでした。

github.com

Node 21.1.xでこの問題は解消されたようですが、LTSバージョンではまだ解消されていないようなので、次のJestオプションでワーカーのメモリ使用量を制限しました。

  ...
  workerIdleMemoryLimit: '1024MB',
  ...

jestjs.io

しかし、workerIdleMemoryLimit オプションを設定しても変わらずメモリエラーでテストが落ちてしまいました。

workerIdleMemoryLimit オプションのバグ

原因について調べてみると、workerIdleMemoryLimitオプションにもバグがあり、ワーカー数が1つだけの場合にオプションが効かないという問題があることがわかりました。

github.com

今回は、特にワーカー数を指定していなかったのですが、Jestの仕様でワーカー数が指定されていない場合、「CPU コア数 - 1」がデフォルトになるようでした。

In single run mode, this defaults to the number of the cores available on your machine minus one for the main thread.

archive.jestjs.io

CIを実行しているコンテナ環境のCPUコア数を調べてみると2コアでしたので、ワーカー数は1つとなっていました。
コンテナ環境のCPUコア数を調べる手順は次の通りです。

// docker または docker-compose コマンドでコンテナに接続する（ここではコンテナ名が `node` になっています）
$ docker-compose exec node /bin/bash

// htop コマンドをインストールする（Debian系のイメージを使っているので `apt` コマンドを用いています）
$ apt install htop

// htop コマンドを実行する（1, 2 と並んでいる数字が CPU コアの情報です）
$ htop
  1  [|||                                                 4.7%]   Tasks: 3, 0 thr; 1 running
  2  [|                                                   1.4%]   Load average: 0.08 0.92 1.04 
  Mem[||||||||||||||||||||||||||||                  974M/7.61G]   Uptime: 00:15:06
  Swp[                                                   0K/0K]

このバグは Jest v29.4.3 で解消されたようですが、maxWorkersオプションでワーカー数を2以上に指定することでも解決できるようだったので、今回はmaxWorkersオプションを指定しました。