1
0

Delete article

Deleted articles cannot be recovered.

Draft of this article would be also deleted.

Are you sure you want to delete this article?

TL;DR

  • EventBridge rate(1 minute) は「毎分0秒ちょうど」でも「毎分ランダムな秒」でもなく、約60秒間隔で、毎分ほぼ同じ秒(0.1秒精度で一定) に発火する
  • 発火位相が「:00秒境界」に近いと、1分粒度で記録したメトリクスに 「見かけ上の欠損」 が生じる。実行は止まっていない
  • 発火位相は disableenable で動かせるが、着地点は予測不能なガチャ。ただし一度当てれば維持される

何が起きたか

依存先サービスの生死とレイテンシを監視するため、Lambda を EventBridge の rate(1 minute) で毎分1回実行し、応答時間(DurationMilliseconds)と受信回数(RequestCount)を CloudWatch のカスタムメトリクスに送っていた。

しばらく運用していると、CloudWatch のグラフで 1分ごとのはずのメトリクスに、ときどき穴が空く ことに気づいた。下は監視対象の1つを6時間ぶん、1分周期で表示したもの。青線が RequestCount(右軸)。

before.png
(画像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 に跳ねているのが見える。これがペアで繰り返されている。

before_zoom.png
(画像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 が残っている。

after1.png
(改修後・6時間。ほぼ 1 だが、稀に 2 が残る)

なぜか。発火位相が :59.5、つまり「:00秒境界」のわずか0.5秒手前にいるからだ。ここに、

  • コールドスタート(実行環境の初期化に数百ms〜1秒近く)
  • あるいは、わずかな発火遅れ+実行時間のわずかな伸びの合わせ技

が乗ると、投入・記録の時刻が 「:00秒境界」を越えて次の分にズレ込む。投入時刻スタンプは「完了までにかかった時間」のズレは吸収できるが、「投入そのものが境界を越える」ケースまでは救えない。

根本原因は「発火が :59.5」

結局、発火位相が「:00秒境界」付近にいる限り、この問題はつきまとう。少しでも後ろにずれれば境界を越えてしまうのだから。

ならば発想を変えて、発火の開始位置そのものを、境界から遠い前半(:10〜:20 あたり)へずらしたい。そこにいれば、多少後ろにずれても次の「:00秒境界」まで十分な余裕がある。

ところが、ここで壁にぶつかる。

  • EventBridge(Rules も Scheduler も)は 秒精度を持たない。「毎分:10 に」という指定はできない
  • cron 式も秒指定不可(分粒度が最小)
  • rate() の位相はルール有効化時刻に依存し、こちらから狙って設定できない

つまり 「発火位相を狙った秒に固定する」は、標準機能では実現できない。

対策2:位相ずらしの方法(ガチャ)

位相を動かす方法はいくつかあるはずだが、おそらく一番簡単なのはルールを disableenable することだ。
ルールを削除して作り直しても動かせるはずだが、CloudFormationやCDKなどでルール作成をしている場合はなおさら disableenable がお勧め。

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)。

after2.png
(位相調整後・6時間。青線が 1 で一定)

after2_zoom.png
(位相調整後・1時間拡大。青線が 1 でフラット、2 も 0 も無い)

1
0
0

Register as a new user and use Qiita more conveniently

  1. You get articles that match your needs
  2. You can efficiently read back useful information
  3. You can use dark theme
What you can do with signing up
1
0

Delete article

Deleted articles cannot be recovered.

Draft of this article would be also deleted.

Are you sure you want to delete this article?