素材フォルダの残りが、思ったほど減っていませんでした。
壁紙アプリのカテゴリ分類を Gemini に任せていて、処理待ちの画像は毎日確実に減っているはずでした。ところが月曜に見た残数と、金曜に見た残数の差が、頭の中の見積もりとどうにも噛み合いません。
ログを開きました。エラーはありません。失敗した実行は一件もありません。分類結果のファイルも、開けばどれも正しく埋まっています。
このとき私が最初に疑ったのは、処理そのものの遅さでした。一回あたりの件数が落ちているのだろう、と。実際には違いました。一回あたりの件数は設計どおりで、回数のほうが半分だった のです。
気づいた手がかりは、失敗ではなく減り方でした
異常の入口は、いつも壊れた成果物だと思い込んでいました。壊れたファイル、落ちたジョブ、赤いアラート。ところがこのときは、出てきたものが全部きれいでした。
きれいなまま、量だけが足りません。
この種の欠落は、監視の構造上どうしても見つけにくくなります。ログは「起きたこと」の記録だからです。起きなかった実行は、そもそも行を持ちません。行がないものを grep することはできません。
私自身、個人開発で動かしている定期処理を10年以上抱えてきましたが、この形の事故を疑う癖はついていませんでした。落ちたら気づく、という前提が身体に染みついていたのだと思います。
成功だけを書くログには、起きなかった実行が映りません
まず、手元にどんな観測点があったかを整理しました。
上二つは、いくら精度を上げても今回の欠落には届きません。観測対象が「呼び出しの中身」に閉じているから です。処理系の外側、つまり成果物と残高の側に立たないと、起きなかった回は見えてきません。
この区別が、後の設計を全部決めました。
未処理の残高から実効スループットを割り出す
最初に手を付けたのは、いちばん粗く、いちばん早く答えが出る計算です。毎朝の残高の推移だけを見ます。
期間中に新規の素材を追加していない棚卸し期間であれば、残高の減少はそのまま消化量になります。
"""未処理キューの残高から、実効スループットが計画を下回っていないかを判定する"""
def drain_rate (backlog: list[ int ]) -> float :
"""1日あたりの平均減少量。正なら消化、負なら滞留している"""
deltas = [backlog[i] - backlog[i + 1 ] for i in range ( len (backlog) - 1 )]
return sum (deltas) / len (deltas)
def days_to_empty (backlog: list[ int ]) -> float | None :
rate = drain_rate(backlog)
return None if rate <= 0 else backlog[ - 1 ] / rate
def plan_ratio (planned_per_run: int , runs_per_day: int , backlog: list[ int ]) -> dict :
"""計画スループットに対する実測の比率。0.5 付近なら回数の欠落を疑う"""
planned = planned_per_run * runs_per_day
observed = drain_rate(backlog)
return {
"planned_per_day" : planned,
"observed_per_day" : round (observed, 1 ),
"ratio" : round (observed / planned, 2 ) if planned else None ,
}
if __name__ == "__main__" :
# 8日分の残高(毎朝同じ時刻に計測・期間中の新規流入なし)
backlog = [ 1180 , 1108 , 1036 , 962 , 890 , 818 , 744 , 672 ]
print ( "平均消化 /日:" , round (drain_rate(backlog), 1 ))
print ( "枯渇まで:" , round (days_to_empty(backlog), 1 ), "日" )
print (plan_ratio( planned_per_run = 72 , runs_per_day = 2 , backlog = backlog))
手元で流したときの出力です。
平均消化 /日: 72.6
枯渇まで: 9.3 日
{'planned_per_day': 144, 'observed_per_day': 72.6, 'ratio': 0.5}
ratio が 0.5 で止まりました。
ここが判断の分かれ目でした。遅延なら比率は日ごとにばらつきます 。0.83、0.71、0.94 といった具合に、負荷や画像サイズに応じて揺れるはずです。ところが 0.5 という割り切れる数字が、きれいに出続けていました。
比率がきれいな分数に張り付いたら、性能ではなく回数を疑います。 この一点だけでも、原因の探索範囲は一気に狭まります。
実際に使った8日分の数値も残しておきます。棚卸し期間として新規の素材追加を止め、毎朝同じ時刻に残数だけを控えました。
減少量が 72 前後でほとんど揺れていません。1回あたり 72 件を上限にしていたので、これは「1回ぶんが毎日きれいに消化されている」という形です。もし処理が遅くなっているだけなら、日ごとに 40 や 60 といったばらつきが出ます。揺れの小ささのほうが、値そのものより雄弁でした 。
私はこの場面では、まず計画比を出してから原因を探すことを推奨します。ログの精読は情報量が多いぶん時間を吸いますが、この計算は残数8個から2分で終わります。順番を逆にしていたら、私はおそらく画像サイズやモデルの応答時間を先に疑って、半日は溶かしていたはずです。
期待スロットと成果物を突き合わせて、欠落した枠を名指しする
比率で当たりを付けたら、次はどの枠が落ちているかを特定します。
やることは単純です。予定の実行時刻を並べ、それぞれに猶予時間を持たせた窓を作り、成果物に残っている完了時刻をその窓へ割り当てていきます。割り当たらなかった窓が、実行されなかった回です。
"""実行スロットの欠落検知(成果物側からの逆算)"""
from __future__ import annotations
from dataclasses import dataclass
from datetime import datetime, timedelta
from zoneinfo import ZoneInfo
JST = ZoneInfo( "Asia/Tokyo" )
@dataclass ( frozen = True )
class Slot :
day: str # "2026-08-26"
label: str # "04:30"
start: datetime
end: datetime # 猶予込みの締切
def expected_slots (days: list[ str ], times: list[ str ], grace_min: int = 90 ) -> list[Slot]:
"""予定表から、猶予つきの受け入れ窓を作る"""
out = []
for d in days:
y, m, dd = map ( int , d.split( "-" ))
for t in times:
hh, mm = map ( int , t.split( ":" ))
start = datetime(y, m, dd, hh, mm, tzinfo = JST )
out.append(Slot(d, t, start, start + timedelta( minutes = grace_min)))
return sorted (out, key =lambda s: s.start)
def observed_runs (records: list[ dict ]):
"""成果物に付いた run_id と完了時刻を、実行の痕跡として取り出す"""
seen = set ()
for r in records:
rid = r.get( "run_id" )
if not rid or rid in seen:
continue
seen.add(rid)
yield datetime.fromisoformat(r[ "finished_at" ]).astimezone( JST )
def reconcile (slots: list[Slot], runs: list[datetime]) -> dict :
"""窓に痕跡を割り当て、余った窓と余った痕跡を分けて返す"""
remaining = sorted (runs)
missed, matched = [], []
for s in slots:
hit = next ((r for r in remaining if s.start <= r <= s.end), None )
if hit is None :
missed.append(s)
else :
matched.append((s, hit))
remaining.remove(hit)
return { "missed" : missed, "matched" : matched, "orphans" : remaining}
if __name__ == "__main__" :
days = [ f "2026-08- { d :02d } " for d in range ( 20 , 28 )]
slots = expected_slots(days, [ "04:30" , "16:30" ])
# 成果物から拾えた完了時刻(04:30 枠のぶんだけが並んでいた)
records = [
{ "run_id" : f "r { i } " , "finished_at" : f " { d } T04:52:00+09:00" }
for i, d in enumerate (days)
]
res = reconcile(slots, list (observed_runs(records)))
print ( f "期待スロット: { len (slots) } 実行痕跡: { len (res[ 'matched' ]) } 欠落: { len (res[ 'missed' ]) } " )
by_label: dict[ str , int ] = {}
for s in res[ "missed" ]:
by_label[s.label] = by_label.get(s.label, 0 ) + 1
for label, n in sorted (by_label.items()):
print ( f " 欠落が集中したスロット { label } : { n } / { len (days) } 日" )
出力はこうなりました。
期待スロット: 16 実行痕跡: 8 欠落: 8
欠落が集中したスロット 16:30: 8/8 日
「たまに落ちている」ではなく、特定の枠が8日間ずっと一度も動いていませんでした 。ここまで出れば、疑うべきは処理系ではなく起動側だと確定します。
orphans を分けて返しているのには理由があります。予定外の時刻に痕跡が残っていた場合、それは手動実行か、猶予時間の設定が短すぎるかのどちらかです。欠落と余りを同じ袋に入れると、この区別が潰れます。
猶予時間は、勘ではなく遅れの実測から決めました
grace_min=90 という数字を、最初はなんとなく置いていました。短すぎれば正常に走った回を欠落と読み、長すぎれば窓が隣の枠まで伸びて、別の回の痕跡を拾います。どちらに倒れても、検知は嘘をつきます。
そこで、予定時刻から実際に処理が始まるまでの遅れを8日ぶん控えて、決め直しました。
"""予定時刻からの遅れの実測から、受け入れ窓の猶予を決める"""
import math
def suggest_grace (delays_min: list[ int ], safety: float = 3.0 , step: int = 15 ) -> int :
"""中央値ではなく最大値を基準にする。猶予は誤報を防ぐための余白なので、
平均的な回ではなく、いちばん遅かった回に合わせる必要がある"""
worst = max (delays_min)
return int (math.ceil(worst * safety / step) * step)
def grace_fits (grace_min: int , times: list[ str ]) -> bool :
"""窓が隣の枠へ食い込んでいないか。食い込むと痕跡の取り違えが起きる"""
mins = sorted ( int (t[: 2 ]) * 60 + int (t[ 3 :]) for t in times)
gaps = [b - a for a, b in zip (mins, mins[ 1 :])] + [ 1440 - mins[ - 1 ] + mins[ 0 ]]
return grace_min < min (gaps)
if __name__ == "__main__" :
delays = [ 2 , 3 , 2 , 4 , 9 , 2 , 3 , 26 ] # 予定時刻から起動までの遅れ(分)
g = suggest_grace(delays)
print ( "いちばん遅かった回:" , max (delays), "分" )
print ( "推奨する猶予:" , g, "分" )
print ( "枠どうしが重ならないか:" , grace_fits(g, [ "04:30" , "16:30" ]))
流した結果です。
いちばん遅かった回: 26 分
推奨する猶予: 90 分
枠どうしが重ならないか: True
26分の遅れが出た日は、同じ時刻に別の重い処理が重なっていた日でした。こういう回をひとつでも欠落として数えてしまうと、翌朝の確認が「たぶん誤報だろう」という気分から始まります。そうなった検知は、いずれ見なくなります。猶予は平均ではなく、いちばん遅かった回に合わせます。
grace_fits を並べて置いたのは、この決め方に上限があるからです。4:30 と 16:30 のように 12 時間あいていれば 90 分はいくらでも収まりますが、1時間おきに回している処理なら、同じ計算で出た 90 分は隣の枠へ食い込みます。窓が重なった時点で、成果物の側からの突き合わせは原理的に当てになりません。
短い間隔で走らせている処理では、ここまでの方法は当たりを付ける道具として使い、どの枠かの名指しは次に書く実行台帳のほうへ任せています。
0件で終わった回にも痕跡を残す
成果物からの逆算には穴があります。処理対象が0件だった回は、成果物を作らない からです。
キューが空の日と、起動しなかった日が、同じ「痕跡なし」として並んでしまいます。これでは検知が誤報を出し始め、いずれ誰も見なくなります。
そこで、Gemini を呼ぶ前に必ず1行書くようにしました。処理件数がゼロでも書きます。
"""起動したこと自体を、処理内容と切り離して記録する"""
import sqlite3
import uuid
from datetime import datetime, timezone
DDL = """
CREATE TABLE IF NOT EXISTS run_heartbeat (
run_id TEXT PRIMARY KEY,
slot_label TEXT NOT NULL, -- "04:30" など予定表側の識別子
started_at TEXT NOT NULL,
finished_at TEXT,
item_count INTEGER -- 0 も正当な値として記録する
);
"""
def open_ledger (path: str = "runs.db" ) -> sqlite3.Connection:
conn = sqlite3.connect(path)
conn.execute( DDL )
conn.commit()
return conn
def begin_run (conn: sqlite3.Connection, slot_label: str ) -> str :
"""Gemini を呼ぶ前に呼ぶ。ここで書かないと不発火と区別できなくなる"""
run_id = uuid.uuid4().hex
conn.execute(
"INSERT INTO run_heartbeat (run_id, slot_label, started_at) VALUES (?, ?, ?)" ,
(run_id, slot_label, datetime.now(timezone.utc).isoformat()),
)
conn.commit()
return run_id
def end_run (conn: sqlite3.Connection, run_id: str , item_count: int ) -> None :
conn.execute(
"UPDATE run_heartbeat SET finished_at = ?, item_count = ? WHERE run_id = ?" ,
(datetime.now(timezone.utc).isoformat(), item_count, run_id),
)
conn.commit()
def missing_slots (conn: sqlite3.Connection, day: str , expected: list[ str ]) -> list[ str ]:
rows = conn.execute(
"SELECT slot_label FROM run_heartbeat WHERE started_at LIKE ? || '%'" , (day,)
).fetchall()
seen = {r[ 0 ] for r in rows}
return [s for s in expected if s not in seen]
begin_run を Gemini の呼び出しより前に置くのが要点です。後ろに置くと、呼び出しで落ちた回の痕跡が消え、また同じ死角ができます。
item_count に 0 を許すのも意図的です。0 は欠測ではなく観測結果です。ここを NULL と混ぜてしまうと、「空だった日」と「動かなかった日」がまた同じ顔になります。
片方の死角を埋めたら、逆側に穴が開きました
台帳を入れた翌週、missing_slots は毎朝きれいな空配列を返すのに、成果物の数は予定に届かない、という日がありました。
原因は自分の設計でした。begin_run を Gemini の呼び出しより前に置いたので、呼び出しの途中で落ちた回も「起動した回」として台帳に残ります。起動の有無だけを見ているかぎり、その回は動いたものとして数えられてしまうのです。
不発火を見えるようにしたら、今度は中断が見えなくなっていた——観測点をひとつ足すたびに、足した場所の裏側を確かめる必要があるのだと思います。
足したのは、終わっていない回を拾うだけの短い関数です。
"""begin_run だけ書かれて finished_at が埋まっていない回を拾う"""
from datetime import datetime, timedelta, timezone
def stuck_runs (conn: sqlite3.Connection, older_than_min: int = 120 ) -> list[tuple[ str , str ]]:
"""不発火とは別種の事故なので、欠落とは分けて数える"""
cutoff = (datetime.now(timezone.utc) - timedelta( minutes = older_than_min)).isoformat()
rows = conn.execute(
"SELECT run_id, slot_label FROM run_heartbeat "
"WHERE finished_at IS NULL AND started_at < ?" ,
(cutoff,),
).fetchall()
return [(r[ 0 ], r[ 1 ]) for r in rows]
older_than_min は、1回の処理にかかる最長時間より十分に長く取ります。私は実測の3倍にしました。猶予の決め方とまったく同じ考え方です。
これで、起動・完了・欠落の三つを同じ表から別々に数えられるかたちになりました。起動を記録した場所には、完了も記録します。 片方だけの台帳は、埋めたつもりの死角を少しずらすだけでした。
分類の中身そのものでつまずいた記録は、Gemini API Embedding で詰まった3か所 に別途まとめてあります。今回の話は、その手前にある「そもそも走ったのか」の層です。
直感に反したのは、予定表をまとめて書いていたことでした
原因は、実行基盤側の予定表の書き方にありました。
1日2回動かしたい処理を、複数の時刻をまとめた一つの予定として登録していたのです。私はこれを、当然どちらの時刻でも起動するものとして書いていました。実際には片方しか発火していませんでした。
予定表を見返しても、書き方は間違って見えません。宣言としては正しく、挙動としては半分 という状態は、読み返しでは絶対に見つかりません。だから成果物の側から数えるしかありませんでした。
対処は単純で、枠ごとに別の予定へ分けました。4:30 の予定と 16:30 の予定を、それぞれ独立した登録にします。まとめて書くほうが管理は楽ですが、まとめた単位はまとめて壊れます。
この教訓は、実行基盤を問わず効くと感じています。並列に動くはずのものを一つの宣言に畳むと、畳んだ内側の欠落が外から見えなくなります。似た構図は、送信間隔の制約を一箇所にまとめてしまった App Store と Google Play のレビュー返信自動化 でも踏んでいました。
毎朝の点検に残した四つの数字
復旧そのものは分割で終わりましたが、同じ死角をもう一度作らないために、朝の確認へ四つだけ数字を出すようにしました。
前日の実行回数と予定回数の差 :missing_slots の戻り値をそのまま出します。空配列でなければ、その時点で調べます
直近7日の計画比 :plan_ratio の ratio。0.9 を割ったら、遅延か欠落かを切り分けます
item_count が 0 だった回数 :これが増え始めたら、キューの供給側が止まっています
終わっていない回の数 :stuck_runs の戻り値の件数。0 でなければ、不発火ではなく中断のほうを追います
四つとも、Gemini の応答品質とは無関係な数字です。モデルの精度を測るダッシュボードは前から持っていましたが、動いたかどうかを測る場所は持っていませんでした 。品質の計測は、実行の計測が前提になっていた、というのが今回いちばん腑に落ちた点です。
モデルを二系統並べて比較したときの記録は Gemini 3 Pro と 2.5 Pro を壁紙カテゴリ分類に並行投入した3週間の実装メモ にありますが、あのときも比較していたのは出力の質だけでした。回数を数える視点は入っていませんでした。
まとめ
いま動いている定期処理のうち、複数の時刻を一つの予定にまとめて書いているものを1件だけ選んで、直近7日の成果物の完了時刻を数えてみてください。予定した回数と一致していれば、それで安心できます。一致しなければ、その日のうちに分割できます。
私自身、まだ他の自動処理を全部は数え直せていません。同じ形の穴がどこかに残っている気がしています。お読みいただきありがとうございました。