配備のたびに、日次の処理が丸ごと走り直していた:48 時間で 477 回、その日の Gemini 費用の 46.6%
トレカダッシュ 開発の記録 / 2026年9月
iOS アプリ「トレカダッシュ」の裏側では、定期的に動く処理がたくさん動いています。その中に、「1 日に 1 回だけ動くはず」の処理がありました。ところが、ある日のログを数えると、その処理が 43 回動いていました。
この記事は、そこから見つかった、「配備(コードを入れ替えて再起動すること)のたびに、日次の処理が丸ごと走り直していた」不具合の記録です。
数字は、2026 年 9 月 1 日の作業の記録から書いています。
48 時間で、477 回の追い実行
処理の実行は、時刻になると動く仕組み(cron)で決まっています。再起動すると、その瞬間にあった予定は、消えます。そこで、起動したときに「前回の実行が古すぎる処理」を探して、取りこぼしとして追いかけて動かす仕組みを入れていました。この追い実行の判断は、「前回の実行時刻が、間隔の 1.05 倍より古いか」でした。
この日の 48 時間で数えると、追い実行は477 回ありました。中でも、記事に商品の紐付けを直す日次の処理は、1 日 1 回のはずが43 回動いていて、その日の Gemini(AI)の費用の46.6%、呼び出しにして 1,295 回を占めていました。やっていたのは、同じ記事に、もう一度 AI で値段を付けているだけで、得られるものは何もありません。
原因:「終わった」という記録が、残っていなかった
この処理は、時間の上限(540 秒)を超えると、「タイムアウトした」と記録されます。ただし、JavaScript には、動いている処理を途中で止める仕組みがないので、タイムアウトと記録されたあとも、本体は最後まで動き続けます。
問題は、「最後の実行時刻」の書き込みが、成功して終わったときだけだったことです。タイムアウトした回は、本体が最後まで終わっても、実行時刻が書かれません。すると、再起動のたびに、こう判断されます。
- この処理の最後の実行は、記録が無い(または古い)。
- 間隔の 1.05 倍より古いから、取りこぼしだ。
- いま走らせよう。
日次の処理が、再起動のたびに、丸ごと走っていました。配備を 1 日に何度かするだけで、日に 43 回です。
直し方:「タイムアウトを記録した」と「走らなかった」は別のこと
タイムアウトと記録されても、本体が最後まで終わったなら、その回は走ったものとして記録するようにしました。失敗して終わったときだけは、記録しません。
この直しは、時間の上限を下げる対策と、必ず対にしておく必要がありました。上限だけを下げても、実行時刻が残らなければ、追い実行は止まりません。
逆の問題:追いかけすぎても、足りなくても困る
この追い実行には、反対の問題もありました。8 月 31 日、私の配備が、朝 8 時ちょうどに重なりました。時刻に動く仕組みは、「その瞬間」にしか発火しないので、8 時のダイジェスト通知が、1 通も送られませんでした。
ダイジェストは、1 日に 5 回(6・8・12・18・21 時)です。平均の間隔は 4.8 時間で、追い実行の下限(6 時間)に届かず、「待てば次が来る」と見なされていました。ところが、利用者にとっては、その時刻を選んでいた人の 1 日ぶんが、消えたのです。
直し方は、利用者への届け物に関わる処理だけ、起動時に「直前の 55 分の予定を取りこぼしていないか」を見て、1 回流す形でした。予定から 10 分たつまでは、まだ走っていないだけかもしれないので、待ちます。
ここで、全部の処理に広げては、いけません。実データで数えたら、再起動のたびに 33 件が「取りこぼし」と判定され、ほとんどは再起動で中断されただけでした。全部を追いかけると、取得サービスや API の上限を、無駄に食います。足す基準は、「取りこぼすと、利用者への届け物が消えるか」です。
分かったこと
「記録が無い」は、「走らなかった」とは限らない。
- 実行の記録は、結果のあとに必ず書く。成功のときだけ書くと、タイムアウトした回が「未実行」に見えます。
- 追い実行は、少なすぎても多すぎても壊れる。届け物は追いかける。それ以外は、次の回を待つ。
- 配備のたびに何が走るかを、数える。48 時間の 477 回は、数えるまで見えていませんでした。
- 同じ記事に、同じ仕事を繰り返すと、費用が溶ける。その日の費用の 46.6% が、何も生まない呼び出しでした。
この話に出てくるもの
- トレカダッシュ — トレカの抽選・予約・先着の情報を集める iPhone アプリ
- Gemini の費用を削る前に、計器を疑った — 同じ費用の、別の見つけ方
- 「取れた」と読んでいたのは、ただの案内ページだった — 記録と実際が食い違っていた、別の失敗
ほかの記録
- 通知は取り消せない:直近 72 時間の通知の 19% が誤通知で、関門が通知の「後」に効いていた — 直近 72 時間に通知した 644 件のうち 122 件(19%)が誤通知だった。記事の関門は後から記事を下げるが、通知は保存の約 0.6 秒後に飛ぶ。下げた 30 件のうち 25 件はもう通知済みだった。通知を送る側の入口に同じ関門を通した記録。
- Gemini の費用を削る前に、計器を疑った:単価・内訳・キャッシュの 3 つが壊れていて、キャッシュの条件は測り直すと変わっていた — Gemini の費用の計測は 3 か所とも壊れていた(単価は 1/2.6 の過小表示、31 の用途が 1 つに潰れ、キャッシュ未計上)。キャッシュが効く条件は 9 月は約 8,000、10 月は約 4,000 トークンと食い違った。指示文を水増しすると判定が 9% ずれた。
- Firestore の費用を円で出したら、読み取りの 91% が 1 か所だった:キャッシュを入れても効かなかった理由 — Firestore を初めて円で見たら、月 1.3 万円で Gemini とほぼ同額だった。読み取りの 91% は商品一覧の読み直し。60 秒キャッシュが効かなかったのは、32 件が同時に動いていたから。「読み込み中の約束」を覚えて直した記録。
コメント
感想や、記事の間違いの指摘は、ここへ。書くには、GitHub のアカウントが要ります。
押すと、giscus(giscus.app)と GitHub に接続します。押さなければ、接続しません。詳しくはあつかいに書いています。