Language: 日本語
setInterval に 720 時間を渡したら、1 ミリ秒になった
フルバイブコーディングで作られたアプリのバックエンドの性能改善として参画し、まずはとりあえずログを眺めていたときのことです。Cloud Logging で妙なログを見つけました。
フルバイブコーディングで作られたアプリのバックエンドの性能改善として参画し、まずはとりあえずログを眺めていたときのことです。Cloud Logging で妙なログを見つけました。
メールアドレスから Slack ID を引くためのマッピング表を読み込んだ、というログが信じられない勢いで流れています。
この処理は、サーバー起動時に一度読み込み、あとは月1回(30日ごと)読み直すだけの設計でした。30日に1回しか出ないはずのログが、画面を開いているあいだに毎秒何百回と吐き出され続けていました。
算数は合っているコード
コードを確認すると、読み込み間隔は環境変数で持っていました。
const reloadIntervalHours = Number(
config.get("EMAIL_SLACK_MAPPING_RELOAD_INTERVAL_HOURS"), // 720
);
// 時間からミリ秒へ変換
const intervalMs = reloadIntervalHours * 60 * 60 * 1000;
setInterval(() => {
reloadEmailSlackMapping();
}, intervalMs);
設定値は 720 時間(24時間 × 30日)。
setInterval はミリ秒を受け取るので、時間からミリ秒へ変換して渡しています。
$$720 \times 60 \times 60 \times 1000 = 2,592,000,000 \text{ ms}$$
計算は合っています。設定値も意図通り30日です。
TypeScript の型も number なので通りますし、AIに「30日ごとにリロードする処理を書いて」と頼んでも平然とこのコードが出てきます。人間のコードレビューでも普通に見逃します。
Node.js タイマーの上限値
原因は、渡したミリ秒が Node.js のタイマーが扱える最大値(32bit 符号付き整数の上限)を超えていたことでした。
Node.js の内部実装(timers.js)にそのロジックがあります。
// lib/internal/timers.js (Node.js v22.22.0 より抜粋)
const TIMEOUT_MAX = 2 ** 31 - 1; // 2,147,483,647
after *= 1;
if (!(after >= 1 && after <= TIMEOUT_MAX)) {
if (after > TIMEOUT_MAX) {
process.emitWarning(
`${after} does not fit into a 32-bit signed integer.` +
`\nTimeout duration was set to 1.`,
'TimeoutOverflowWarning'
);
}
after = 1;
}
this._repeat = isRepeat ? after : null;
TIMEOUT_MAX は $2^{31} - 1 = 2,147,483,647$ ミリ秒です。
今回渡した 2,592,000,000 は、これを超えています。
上限を超えると、Node.js はプロセスを落とさず、遅延時間(after)を 1 ミリ秒に強制的に書き換えます。
setInterval ではこの 1 がそのまま次回以降のリピート間隔(this._repeat)に入るため、30日ごとの定期実行が、1ミリ秒ごとの超高頻度ループになっていました。間隔を長く設定したつもりが、Node.js で設定できる最短間隔で回り始めます。
警告が出るタイミング
ここで厄介なのが、TimeoutOverflowWarning が出るタイミングです。
この警告は setInterval を登録した瞬間(=サーバー起動時)に 1 回だけ出る もので、実行時には一切出ません。
[起動時] (node:1234) TimeoutOverflowWarning: 2592000000 does not fit into a 32-bit signed integer. Timeout duration was set to 1.
[1ms後] [INFO] reloadEmailSlackMapping done
[2ms後] [INFO] reloadEmailSlackMapping done
[3ms後] [INFO] reloadEmailSlackMapping done
...
コンテナが立ち上がってしばらく経った本番環境のログを眺めても、最初の警告はとうの昔に流れて見えません。画面には「マッピングを読み込んだ」という正常ログだけが秒間数百回で埋め尽くされている状態になります。
エラーで例外が飛ぶわけでもなく、出ているログ自体は正常なので、メトリクス監視やアラートにも引っかかりにくいです。
24.8 日という境界
2,147,483,647 ミリ秒を日数に直すと、約 24.8 日になります。
$$2,147,483,647 \div (1000 \times 60 \times 60 \times 24) \approx 24.855 \text{ 日}$$
つまり、約 25 日を超える間隔をミリ秒で setTimeout や setInterval に渡すと、すべて 1 ミリ秒になります。
- 1 日後や 1 週間後:動く
- 20 日後:動く
- 30 日後(月次):1ms に化ける
日次や週次のバッチ感覚で「30日だから 720 * 60 * 60 * 1000」と書くと踏みます。
直し方
一番手っ取り早くて確実な解決策は、月次の定期実行を Node.js プロセス内のタイマーで抱えるのをやめて、Cloud Scheduler に任せること です。
そもそも 30 日もの長いタイマーをプロセスのメモリ内で維持しようとする設計自体、デプロイや再起動のたびにタイマーがリセットされるため筋が良くありません。
リロード用の API エンドポイントを用意して Cloud Scheduler から月 1 回叩くようにすれば、Node.js の 32bit 整数上限に怯える必要もなくなります。
アプリ側で応急処置をするなら、値をクランプするガードを入れます。
const TIMEOUT_MAX = 2_147_483_647; // 2^31 - 1 (約24.8日)
const safeIntervalMs = Math.min(intervalMs, TIMEOUT_MAX);
ただ、これでも最大で約 24.8 日後には発火してしまうため、やはり長い周期の定期処理は外部スケジューラ一発で解決するのが一番シンプルです。
動いているように見えてもログを眺める
Web アプリの性能改善というと「遅い SQL を直す」みたいなレイテンシの短縮ばかり考えがちですが、「1回は軽い処理が異常な回数で発火している」というパターンもあります。
最近はバイブコーディングでサクッと動くものを作る場面も増えました。しかし、AI も人間も「算数は合っているし型も通るけれど、ランタイムの暗黙の制約を踏んでいるコード」を普通に書きます。
動いているように見えても、一度ちゃんと Cloud Logging を眺めてみましょう。「30日に1回のはずのログが秒間数百回流れている」ような怪奇現象に気づけるのは、結局のところログを見た瞬間だけです。