TL;DR
- EventBridge
rate(1 minute)は「毎分0秒ちょうど」でも「毎分ランダムな秒」でもなく、約60秒間隔で、毎分ほぼ同じ秒(0.1秒精度で一定) に発火する - 発火位相が「:00秒境界」に近いと、1分粒度で記録したメトリクスに 「見かけ上の欠損」 が生じる。実行は止まっていない
- 発火位相は
disable→enableで動かせるが、着地点は予測不能なガチャ。ただし一度当てれば維持される
何が起きたか
依存先サービスの生死とレイテンシを監視するため、Lambda を EventBridge の rate(1 minute) で毎分1回実行し、応答時間(DurationMilliseconds)と受信回数(RequestCount)を CloudWatch のカスタムメトリクスに送っていた。
しばらく運用していると、CloudWatch のグラフで 1分ごとのはずのメトリクスに、ときどき穴が空く ことに気づいた。下は監視対象の1つを6時間ぶん、1分周期で表示したもの。青線が RequestCount(右軸)。

(画像1:改修前・6時間。青線 RequestCount が 1 と 2 を乱高下している)
毎分実行するんだから青線は 1 だけで真っ直ぐのはずなのに、記録のないところ(欠損)、2 になっているところ(スパイクのように見える)が混在している。
最初に疑うのは「Lambda がときどき失敗している / 実行されていない」だが、結論から言うとそうではなかった。実行は毎分きっちり行われていて、成功もしていた。 それなのにグラフには穴が空く。この記事はその謎を追った記録である。
前提:ちゃんと毎分動いている
まず Lambda の実行ログ(REPORT 行)を数えると、穴が空いて見える時間帯でも、毎分1回きっちり実行され、すべて成功していた。タイムアウトもエラーもゼロ。PutMetricData もエラーなく呼ばれている。
つまり「観測は継続している」。にもかかわらずメトリクスのグラフには欠損が見える。ということは、問題は「実行」ではなく「記録のされ方」 にある。
発見その1:発火は「毎分0秒」ではない
実行開始ログ(START)のタイムスタンプの「秒」だけを集計してみた。3日分、約4300回ぶん。
4314回 :59
6回 :00
99.7% が :59 秒に発火していた。 rate(1 minute) は「毎分0秒」でも「0〜59のランダム」でもなく、毎分ほぼ同じ秒に張り付いて発火する(この秒がどこになるかはこちらから指定できない。どう決まるかは後述)。
さらにミリ秒(0.1秒バケット)まで見ると、:59 は単一の点ではなく :59.5 付近の一点 に鋭く集中していた。整数秒で :59 に見えていたのは丸めの結果で、実体は :59.5 というほぼ一点だった。
別の監視対象では位相が :13.0 に集中していた(こちらは「:00秒境界」から遠く、後述の問題が起きない)。同じ設定でも、監視対象(ルール)ごとに発火位相はバラバラ で、運任せに決まる。
発見その2:見かけ上の欠損の正体
rate(1 minute) は「前回発火からおよそ60秒後」に次のトリガを引く。その結果「1分に1回」の実行となっている。
ところが、CloudWatch のカスタムメトリクスは(Timestamp を明示しないと)PutMetricData を呼んだ時刻=ハンドラ完了時刻 でデータ点を記録する。発火が :59.5 で、実行に数百ms かかると、完了は次の「:00秒境界」を少し越える。すると
- 発火は「その分」にあったのに
- メトリクスの記録時刻は「次の分」にズレる
結果、ある分にはデータ点が0個、隣の分には2個 という状態が生まれる。下の拡大図で、青線が 0 (=欠損)で途切れた直後に 2 に跳ねているのが見える。これがペアで繰り返されている。

(画像2:改修前・1時間拡大。0点の分と2点の分がペアで出ている)
START(発火=実行開始)のログを見ると、欠損しているように見える分にもちゃんと発火があった。ただその回の完了が「:00秒境界」を越え、メトリクスが隣の分に記録されただけ。発火は1回も抜けていない。
いずれにせよ、発火が「:00秒境界」の近くにあり、記録を1分粒度で見るかぎり、処理がほんの少し遅れただけで隣にズレ込む。「実行は毎分1回きっちり」なのに、グラフ上は欠損と2重が対で現れる。これが「見かけ上の欠損」の正体だ。
対策1:記録時刻を「投入時刻」にする
PutMetricData は各データ点に Timestamp を明示指定できる。そこで、「リクエストを投げる直前の時刻」 を全メトリクスの Timestamp に指定するようにした。
意味論としても、これが正しい。「XX:YY:ZZ に投げたリクエストが N ミリ秒かかった」という記録にしたいのであって、「いつ完了したか」で記録したいわけではない。
これで、実行時間で完了が後ろにずれても、データ点は「投げた時刻」の分に収まる。
はずだった。
でも、まだたまにズレる
ところが、対策1を入れてもなお、ごく稀に青線が 2 に跳ねる。下は改修後の6時間。ほとんど 1 で平らだが、18:00 前後と 20:00 過ぎに 2 が残っている。
なぜか。発火位相が :59.5、つまり「:00秒境界」のわずか0.5秒手前にいるからだ。ここに、
- コールドスタート(実行環境の初期化に数百ms〜1秒近く)
- あるいは、わずかな発火遅れ+実行時間のわずかな伸びの合わせ技
が乗ると、投入・記録の時刻が 「:00秒境界」を越えて次の分にズレ込む。投入時刻スタンプは「完了までにかかった時間」のズレは吸収できるが、「投入そのものが境界を越える」ケースまでは救えない。
根本原因は「発火が :59.5」
結局、発火位相が「:00秒境界」付近にいる限り、この問題はつきまとう。少しでも後ろにずれれば境界を越えてしまうのだから。
ならば発想を変えて、発火の開始位置そのものを、境界から遠い前半(:10〜:20 あたり)へずらしたい。そこにいれば、多少後ろにずれても次の「:00秒境界」まで十分な余裕がある。
ところが、ここで壁にぶつかる。
- EventBridge(Rules も Scheduler も)は 秒精度を持たない。「毎分:10 に」という指定はできない
-
cron式も秒指定不可(分粒度が最小) -
rate()の位相はルール有効化時刻に依存し、こちらから狙って設定できない
つまり 「発火位相を狙った秒に固定する」は、標準機能では実現できない。
対策2:位相ずらしの方法(ガチャ)
位相を動かす方法はいくつかあるはずだが、おそらく一番簡単なのはルールを disable → enable することだ。
ルールを削除して作り直しても動かせるはずだが、CloudFormationやCDKなどでルール作成をしている場合はなおさら disable → enable がお勧め。
aws events disable-rule --name "XXX" ; aws events enable-rule --name "XXX"
動かした結果は、次の発火で分かる。何度か試行して、disable した秒・enable した秒・停止していた時間、それぞれの結果との位相の関係を調べたが、
- enable した秒に揃う? → 揃わない
- disable した秒に揃う? → 揃わない
- 停止時間ぶんずれる? → 合わない(7秒停止で47秒ずれた回もあった)
結論、着地点は予測できない。完全なガチャ。狙って :10〜:20 に置くことはできず、「引いては次の発火を見て、外れたらまた引く」を繰り返すしかない。当たり幅を10秒とすると、1回あたりの当たりはざっくり 1/6。
救いは、一度当てれば維持される こと。当てた位相は数日にわたって動かなかった(0.1秒精度で同じ点に張り付いたまま)。
結果
ガチャを引いて位相を前半に寄せた。以下が最終結果。6時間でも、1時間に拡大しても、青線は 1 で張り付き、0 も 2 も無い(縦軸は先ほどと統一。着目は青線 RequestCount)。


