本文へスキップ
株式会社Virtex

Tech Blog

CPUが2コアだとjestは終わらない — in-band実行とpendingのままのMutation

目次

CI のモバイルのテストは、30 分のタイムアウトまで終わらなかった。手元で同じ jest を叩くと、1483 件がちゃんと緑で終わる。違いは CPU のコア数だけだった。

この記事は、React Native(Expo)と TanStack Query のアプリで起きた「CI でだけ jest が終わらない」問題の調査記録だ。原因は次の 2 つの組み合わせだった。

  • CI ランナーが 2 コアなので、jest がワーカーを使わず本体プロセスでテストを走らせていた
  • TanStack Query が、pending のままの Mutation の削除タイマーを 5 分ごとに張り直し続けていた

こんな人向け

  • React Native と TanStack Query のアプリで、CI の jest が Jest did not exit やタイムアウトで止まるのに、手元では再現しない
  • --detectOpenHandles を付けても何も出ず、--forceExit で黙らせようか迷っている
  • GitHub Actions のランナーと多コアの開発機で、テストの結果が食い違ったことがある

環境

項目バージョン
jest29.7.0
jest-expo54.0.17
React Native0.81 系
@tanstack/query-core5.99.0
CIGitHub Actions ubuntu-latest(2 コア)
手元10 コアの Mac

1. 症状:CI でだけ終わらない

テストは 241 ファイル・1483 件。手元では数十秒で全部緑になる。CI では lint・test・build をまとめたジョブが 30 分のタイムアウトに達し、mobile の jest の途中でキャンセルされていた。

実はこの CI は、しばらく赤のまま放置されていた。別の静的検査で先に落ちていたので、jest まで処理が進んでいなかったのだ。その検査を直したら、今度は jest が終わらなくなった。

まず「遅いだけなのか、止まっているのか」を切り分けるため、mobile の jest だけを単独のステップに切り出して CI で回した。

.github/workflows/ci.yml

# 調査用の一時ステップ。原因が分かったら消す
- name: "[diag] mobile jest"
  timeout-minutes: 12
  continue-on-error: true
  working-directory: apps/mobile
  run: |
    nproc
    free -m
    npx jest --listTests | wc -l
    npx jest --ci --verbose=false 2>&1

nproc は 2 だった。テストは全部パスしているのに、最後の結果が出たあと jest プロセスが終わらない。遅いのではなく、止まっていた。

2. 2 コアで何が変わるのか

jest のワーカー数の既定は「コア数 − 1」だ。

jest-config/build/getMaxWorkers.js

Math.max(
  isWatchModeEnabled ? Math.floor(numCpus / 2) : numCpus - 1,
  1,
)

2 コアなら 1 になる。そしてワーカーが 1 つ以下だと、jest はワーカーを立てずに本体プロセスで直接テストを走らせる。これを in-band 実行という。

@jest/core/build/testSchedulerHelper.js

if (runInBand || detectOpenHandles) {
  return true;
}
// ...
const oneWorkerOrLess = maxWorkers <= 1;
const oneTestOrLess = tests.length <= 1;
return (
  !workerIdleMemoryLimit &&
  (oneWorkerOrLess ||
    oneTestOrLess ||
    (tests.length <= 20 && timings.length > 0 && areFastTests))
);

この違いが、タイマーが残ったときの挙動を分ける。

実行方式タイマーが 1 つ残ったとき
in-band(CI の 2 コア)本体プロセスのイベントループが空にならず、プロセスが終わらない
ワーカー(手元の 10 コア)警告を 1 行出してワーカーごと強制終了し、exit 0 で終わる

手元で出ていたのは、この警告だけだった。

A worker process has failed to exit gracefully and has been force exited.
This is likely caused by tests leaking due to improper teardown.
Try running with --detectOpenHandles to find leaks.
Active timers can also cause this, ensure that .unref() was called on them.

つまり手元の緑は、ワーカーの強制終了が問題を隠した結果だった。手元で CI と同じ状況を作るには、-i(--runInBand)を付ければいい。

CI=true npx jest --ci -i

これで手元でも止まるようになった。

テストが 20 ファイル以下で、前回の実行がどれも速かった場合も、jest は多コアでも in-band 実行を選ぶ(上のコードの最後の条件)。小さな再現プロジェクトを作ると、-w 2 を付けても止まることがあるので注意したい。

3. --detectOpenHandles は黙っている

残ったタイマーを探すなら、まず --detectOpenHandles だ。これを付けると in-band 実行が強制される(上のコードの最初の条件)。

ところが今回は、止まっているのに何も報告されなかった。報告されたのはタイマーのごく一部で、犯人は出てこなかった。

そこで、setTimeout を横取りして「どこで作られ、まだ消えていないタイマー」を記録する仕込みを入れた。NODE_OPTIONS=--require で jest より先に読み込ませる。考え方は次のとおりだ。

trace-timers.js

// 生きているタイマーと、それを作った場所のスタックを記録する
const live = new Map();
const origSetTimeout = global.setTimeout;
const origClearTimeout = global.clearTimeout;

global.setTimeout = function (cb, ms, ...args) {
  const stack = new Error().stack;
  const t = origSetTimeout(function () {
    live.delete(t);
    return cb.apply(this, arguments);
  }, ms, ...args);
  live.set(t, { ms, stack });
  return t;
};

global.clearTimeout = function (t) {
  live.delete(t);
  return origClearTimeout(t);
};

// 定期的に件数と、作成場所ごとの内訳を出す
const report = origSetTimeout(function tick() {
  const byStack = new Map();
  for (const { stack } of live.values()) {
    const key = stack.split("\n").slice(2, 6).join("\n");
    byStack.set(key, (byStack.get(key) ?? 0) + 1);
  }
  process.stderr.write(`[timers] live=${live.size}\n`);
  for (const [k, n] of [...byStack].sort((a, b) => b[1] - a[1]).slice(0, 3)) {
    process.stderr.write(`  x${n}\n${k}\n`);
  }
  origSetTimeout(tick, 10_000).unref();
}, 10_000);
report.unref();
NODE_OPTIONS="--require ./trace-timers.js" CI=true npx jest --ci -i

最初に入れたときは、こうなって jest が起動すらしなかった。

Tests:       0 total
Time:        2.945 s, estimated 46 s

仕込みを調整して入れ直し、ようやく記録が取れた。

全テストが終わった時点で、生きているタイマーは 252 個あった。それが約 5 分かけて 65 個、1 個と減っていく。ほとんどのスタックが指していたのは、TanStack Query の内部だった。

4. 犯人:pending のままの Mutation が gc を永久に張り直す

5 分のタイマーが 250 個

TanStack Query は、使われなくなった Query や Mutation を gcTime(既定 5 分)たってからキャッシュから消す。そのために 5 分の setTimeout を張る。

テストでは、ファイルごと・テストごとに QueryClient を作るのが普通だ。今回のテストでも 64 ファイルがそれぞれ自前の QueryClient を作っていた。テストが終わっても、そこで張られた 5 分のタイマーは残る。これが 252 個の正体で、5 分たつと順に発火して消えていった。

ここまでなら「5 分待てば終わる」だけだ。最後の 1 個がいつまでも消えなかった。

pending の Mutation は消えない

最後の 1 個は、Mutation の gc タイマーだった。mutation.ts を見ると、こうなっている。

@tanstack/query-core/src/mutation.ts

protected optionalRemove() {
  if (!this.#observers.length) {
    if (this.state.status === 'pending') {
      this.scheduleGc()            // pending なら 5 分後にもう一度予約する
    } else {
      this.#mutationCache.remove(this)
    }
  }
}

pending の Mutation は削除されず、5 分後の削除予約をし直す。5 分後にまだ pending なら、また予約する。終わらない。

そして、該当するテストがあった。楽観的更新の「リクエスト完了前のキャッシュ」を検証するために、絶対に resolve しない Promise を返していた。

usePreferences.test.ts(修正前)

// リクエスト完了前の状態を検証したい
mockPatch.mockReturnValue(new Promise(() => {}));

const { result } = renderHook(() => useUpdatePreferences(), { wrapper });
act(() => result.current.update({ enabled: true }));

await waitFor(() => {
  const cache = queryClient.getQueryData(PREFERENCES_QUERY_KEY);
  expect(cache?.enabled).toBe(true);
});

この Mutation は永久に pending のままになる。つまり 5 分ごとに永久にタイマーを張り直す。queryClient.clear() を呼んでも、このタイマーは止まらなかった。

なぜ React Native(と jsdom)だけで起きるのか

gcTime の既定値は、実行環境で変わる。

@tanstack/query-core/src/removable.ts

newGcTime ?? (environmentManager.isServer() ? Infinity : 5 * 60 * 1000)

@tanstack/query-core/src/utils.ts

export const isServer = typeof window === 'undefined' || 'Deno' in globalThis

window が無い環境はサーバー扱いになり、gcTime は Infinity になる。Infinity なら gc のタイマー自体が張られない。素の Node 環境で TanStack Query をテストしても、この問題は起きない。

ところが React Native の jest プリセットは、jest/setup.js で window を global として定義している。jest の環境は Node なのに、TanStack Query からはブラウザに見える。だから 5 分のタイマーが張られる。jsdom 環境でも同じだ。

最小構成で確かめる

pending のまま残る Mutation を 1 件持つテストファイルに、ダミーのテストファイル 25 個を足して計 26 ファイルにし、window = global の条件で回した。

条件結果
-i、または --maxWorkers=1終わらない(20 秒で強制終了)
-w 2「force exited」の警告だけ出て exit 0
-i --detectOpenHandles何も報告せずに止まる
window 未定義(純粋な Node 環境)すぐ終わる
setTimeoutProvider で unrefすぐ終わる
mutations.gcTime: Infinityすぐ終わる

CI と手元の差、--detectOpenHandles の沈黙、React Native でだけ起きる理由が、すべてこの表で再現できた。

5. 直し方

直したのは 3 か所だ。

TanStack Query のタイマーをすべて unref する

TanStack Query v5 には、内部で使うタイマーの実装を差し替える timeoutManager.setTimeoutProvider がある。これで、TanStack Query が作るタイマーをすべて unref() する。unref したタイマーは、残っていてもプロセスの終了を妨げない。

jest.setup.js

// TanStack Query の内部タイマー(gcTime 既定 5 分の gc タイマーなど)を unref する。
// テストごとに QueryClient を作るため、全テスト完了後もタイマーが残り、
// in-band 実行では jest プロセスの終了を最大 5 分遅らせる。
// global の setTimeout は呼び出し時に参照し、jest のフェイクタイマーとの連携を保つ。
const { timeoutManager } = require("@tanstack/react-query");

function unrefTimer(timerId) {
  if (typeof timerId?.unref === "function") {
    timerId.unref();
  }
  return timerId;
}

timeoutManager.setTimeoutProvider({
  setTimeout: (callback, delay) => unrefTimer(setTimeout(callback, delay)),
  clearTimeout: (timeoutId) => clearTimeout(timeoutId),
  setInterval: (callback, delay) => unrefTimer(setInterval(callback, delay)),
  clearInterval: (intervalId) => clearInterval(intervalId),
});

setTimeout を provider の外で掴まず、呼び出すたびに参照しているのがポイントだ。テストで jest.useFakeTimers() を使うと global の setTimeout が差し替わるので、それに追従できる。

timeoutManager は TanStack Query v5 の後半で追加された API だ。古い v5 には無いので、使えない場合は後述の gcTime: Infinity を検討してほしい。

絶対に resolve しない Promise を mutate に渡さない

unref でプロセスは終わるようになるが、永久 pending の Mutation はテストとしても行儀が悪い。resolve を手元に持っておき、検証のあとで完了させる。

usePreferences.test.ts(修正後)

// リクエスト完了前の状態を検証するため、resolve を手元に保持して応答を保留する。
// 永久 pending のまま残すと Mutation の gc タイマーが再スケジュールされ続けるため、
// 検証後に必ず完了させる。
let resolvePatch: (value: { data: PreferencesResponse }) => void = () => {};
mockPatch.mockReturnValue(
  new Promise((resolve) => {
    resolvePatch = resolve;
  }),
);

const { result } = renderHook(() => useUpdatePreferences(), { wrapper });
act(() => result.current.update({ enabled: true }));

await waitFor(() => {
  const cache = queryClient.getQueryData(PREFERENCES_QUERY_KEY);
  expect(cache?.enabled).toBe(true);
});
expect(result.current.isPending).toBe(true);

await act(async () => {
  resolvePatch({ data: { ...INITIAL_PREFERENCES, enabled: true } });
});
await waitFor(() => expect(result.current.isPending).toBe(false));

new Promise(() => {}) は「待ち状態を作る」ための定番の書き方だが、TanStack Query の Mutation に渡すと今回の問題を起こす。チームではこの書き方を禁止にした。

テスト終了後も動く Animated.timing を止める

タイマーを片付けて in-band 実行で最後まで走るようになると、今度は exit code 1 で終わった。テスト終了後のログに、このエラーが約 240 件出ていた。

ReferenceError: You are trying to access a property or method of the Jest environment after it has been torn down.

トーストやバナーのテストで、Animated.timing がテストファイル終了後も動き続けていた。Animated.timing は requestAnimationFrame、つまり実際の setTimeout でフレームを進める。テストが終わってもアニメーションは止まらず、破棄済みの jest 環境に触って落ちる。

ワーカー実行ではこれもワーカーの強制終了に隠れていた。該当する 2 ファイルで、フェイクタイマーにアニメーションを閉じ込めた。

Toast.test.tsx

// Animated.timing は実タイマーでフレームを進めるため、実タイマーのままだと
// テストファイル終了後もアニメーションが走り続け、破棄済みの jest 環境へアクセスする。
jest.useFakeTimers();

結果

修正前修正後
手元の in-band 実行終わらない47 秒
CI(2 コア)30 分でタイムアウト3 分

gcTime: Infinity ではダメなのか

TanStack Query の公式ドキュメント寄りの対策は、テスト用の QueryClient に gcTime: Infinity を指定することだ。gc のタイマー自体を張らせない。上の最小構成でも、これで止まることを確認している。

const queryClient = new QueryClient({
  defaultOptions: {
    queries: { retry: false, gcTime: Infinity },
    mutations: { gcTime: Infinity },
  },
});

それでも unref を選んだのは、QueryClient を作っている場所が多すぎたからだ。今回のテストでは 64 ファイルがそれぞれ自前の QueryClient を作っていて、共通のヘルパーも無かった。gcTime: Infinity にするには全ファイルを書き換えるか、ヘルパーを作って全ファイルを移行する必要がある。しかも、新しいテストで指定を忘れたら再発する。

setTimeoutProvider なら jest.setup.js の 1 か所で済み、今後書かれるテストにも効く。使い分けはこう考えている。

対策向いている場面
gcTime: Infinityテスト用の QueryClient を共通ヘルパーで作っている。タイマーを張らせないほうが素直
setTimeoutProvider で unrefQueryClient の生成があちこちに散っている。アプリ側のシングルトンの QueryClient もテストで読み込まれる

どちらを選んでも、永久 pending の Mutation を作らないことは別に守ったほうがいい。unref はプロセスの終了を妨げなくするだけで、Mutation が pending のまま残ること自体は変わらない。

6. 持ち帰ること

  • CI でだけ出る差分は、コア数からも生まれる。2 コアのランナーでは jest は in-band 実行になる
  • 「ワーカーなら通る」は、緑ではなく強制終了で黙らせた結果かもしれない。force exited の警告 1 行を見逃さない
  • CI でだけ止まるなら、まず手元で -i を付けて、CI と同じ 1 プロセスにして再現する
  • --detectOpenHandles が黙っていたら、setTimeout を横取りして作成場所を記録する
  • React Native の jest 環境は、TanStack Query からはブラウザに見える。gcTime の既定は 5 分になる

--forceExit を付ければ、今回の CI もとりあえず緑になったはずだ。ただそれだと、永久 pending の Mutation も、破棄済みの環境に触るアニメーションも、気づかないまま残っていた。手元の緑は、多コアのワーカーが失敗を握りつぶしてくれた結果かもしれない。

Author

細岡 希夢ExecutiveDirector

プロフィールを見る

関連記事

Contact

まずは、話してみませんか。

要件が固まっていなくても大丈夫です。課題をうかがい、進め方と概算をご提案します。

  • ご相談・お見積りは無料
  • 1 営業日以内にご返信
  • NDA(秘密保持契約)の締結も可能

文章で相談する

文章で内容をお送りください。1 営業日以内に担当者からご返信します。

フォームで相談する

日程を選んで話す

カレンダーから空いている日時を選ぶだけ。30 分・無料です。

日程を予約する

採用情報をお探しの方は 採用ページへ