Amazon CloudFront の Request Collapsing (リクエストの折りたたみ)が待機する「短時間」を検証しました

いわさです。

先日以下の記事にて CloudFront のリクエスト折りたたみ機能を紹介しました。

こちら、ドキュメントには以下のように記述されています。

CloudFront は一時停止してから、追加のリクエストをオリジンに転送します。この短い一時停止により、オリジンでの負荷を減らすことができます。

短い一時停止とは何を指しているのでしょうか。
本日はこの一時停止について調べてみました。

リクエストの待機時間を長くしてみる

前回は、レスポンスが返却されるまでに 20 秒必要なエンドポイントに対して 1 秒間で 10 件のリクエストを送信しました。
こちらをさらに長くしてみます。

まずはスリープ時間を 50 秒にしてみました。TTL は 300 秒です。

すると全て 504 Gateway Time-out になってしまいました。
これはリクエスト折りたたみは関係なくて、以下の設定で CloudFront がオリジンからの応答を待機する秒数を設定することが出来ます。

こちらをオリジンのレスポンス時間より長く設定することでタイムアウトエラーを回避することが出来ます。

で、タイムアウトエラーが起きないようにして試してみたのですが結果としては折りたたまれました。
どうやらオリジンのレスポンスタイムと折りたたみの一時停止は関係ないようです。

10.0.0.225 - - [26/Oct/2022:00:20:32 +0000] "GET / HTTP/1.1" 200 14 "-" "ELB-HealthChecker/2.0"
10.0.1.134 - - [26/Oct/2022:00:20:35 +0000] "GET / HTTP/1.1" 200 14 "-" "ELB-HealthChecker/2.0"
10.0.0.225 - - [26/Oct/2022:00:20:42 +0000] "GET / HTTP/1.1" 200 14 "-" "ELB-HealthChecker/2.0"
10.0.1.134 - - [26/Oct/2022:00:20:45 +0000] "GET / HTTP/1.1" 200 14 "-" "ELB-HealthChecker/2.0"
10.0.1.134 - - [26/Oct/2022:00:20:47 +0000] "GET / HTTP/1.1" 200 14 "-" "Amazon CloudFront"
10.0.0.225 - - [26/Oct/2022:00:20:52 +0000] "GET / HTTP/1.1" 200 14 "-" "ELB-HealthChecker/2.0"
10.0.1.134 - - [26/Oct/2022:00:20:55 +0000] "GET / HTTP/1.1" 200 14 "-" "ELB-HealthChecker/2.0"

TTL を短くしてみる

先程は TTL が長すぎたのかもと思いました。
短時間の待機が TTL を意味している可能性もあるのかなと。

そこで TTL を 10 秒に設定して試してみました。

10.0.1.134 - - [26/Oct/2022:00:25:25 +0000] "GET / HTTP/1.1" 200 14 "-" "ELB-HealthChecker/2.0"
10.0.0.225 - - [26/Oct/2022:00:25:32 +0000] "GET / HTTP/1.1" 200 14 "-" "ELB-HealthChecker/2.0"
10.0.1.134 - - [26/Oct/2022:00:25:35 +0000] "GET / HTTP/1.1" 200 14 "-" "ELB-HealthChecker/2.0"
10.0.0.225 - - [26/Oct/2022:00:25:40 +0000] "GET / HTTP/1.1" 200 14 "-" "Amazon CloudFront"
10.0.0.225 - - [26/Oct/2022:00:25:42 +0000] "GET / HTTP/1.1" 200 14 "-" "ELB-HealthChecker/2.0"
10.0.1.134 - - [26/Oct/2022:00:25:46 +0000] "GET / HTTP/1.1" 200 14 "-" "ELB-HealthChecker/2.0"

結果は変わらず折りたたまれました。
TTL まで待機するという仮説は誤っていたようです。

瞬間的ではなくゆっくり送ってみる

先程は 1 秒間に 3 件のリクエストを送信していました。
次は 10 秒かけて 3 件のリクエストを送信してみましょう。

10.0.0.225 - - [26/Oct/2022:00:49:23 +0000] "GET / HTTP/1.1" 200 14 "-" "ELB-HealthChecker/2.0"
10.0.1.134 - - [26/Oct/2022:00:49:26 +0000] "GET / HTTP/1.1" 200 14 "-" "ELB-HealthChecker/2.0"
10.0.0.225 - - [26/Oct/2022:00:49:33 +0000] "GET / HTTP/1.1" 200 14 "-" "ELB-HealthChecker/2.0"
10.0.0.225 - - [26/Oct/2022:00:49:35 +0000] "GET / HTTP/1.1" 200 14 "-" "Amazon CloudFront"
10.0.1.134 - - [26/Oct/2022:00:49:36 +0000] "GET / HTTP/1.1" 200 14 "-" "ELB-HealthChecker/2.0"
10.0.0.225 - - [26/Oct/2022:00:49:43 +0000] "GET / HTTP/1.1" 200 14 "-" "ELB-HealthChecker/2.0"
10.0.1.134 - - [26/Oct/2022:00:49:45 +0000] "GET / HTTP/1.1" 200 14 "-" "Amazon CloudFront"
10.0.1.134 - - [26/Oct/2022:00:49:46 +0000] "GET / HTTP/1.1" 200 14 "-" "ELB-HealthChecker/2.0"
10.0.0.225 - - [26/Oct/2022:00:49:53 +0000] "GET / HTTP/1.1" 200 14 "-" "ELB-HealthChecker/2.0"
10.0.0.225 - - [26/Oct/2022:00:49:55 +0000] "GET / HTTP/1.1" 200 14 "-" "Amazon CloudFront"
10.0.1.134 - - [26/Oct/2022:00:49:56 +0000] "GET / HTTP/1.1" 200 14 "-" "ELB-HealthChecker/2.0"

おお！なんと折りたたまれませんでした。
3 件のリクエストはそれぞれオリジンアクセスが発生しています。

これはどうやらキャッシュがない状態で受け取った最初のリクエストから数秒間を「短い一時停止時間」ということのようです。

一時停止時間を特定する

あとはこの秒数を変更して一時停止時間を探ってみました。

1 秒間隔 で 3 件送信 → 折りたたまれた 2 秒間隔 で 3 件送信 → 折りたたまれた 3 秒間隔 で 3 件送信 → 折りたたまれた 4 秒間隔 で 3 件送信 → 2 件が折りたたまれた、1件は折りたたみの対象外となり、オリジンリクエストは 2 件発生

10.0.0.225 - - [26/Oct/2022:01:01:23 +0000] "GET / HTTP/1.1" 200 14 "-" "ELB-HealthChecker/2.0"
10.0.1.134 - - [26/Oct/2022:01:01:27 +0000] "GET / HTTP/1.1" 200 14 "-" "ELB-HealthChecker/2.0"
10.0.0.225 - - [26/Oct/2022:01:01:33 +0000] "GET / HTTP/1.1" 200 14 "-" "ELB-HealthChecker/2.0"
10.0.0.225 - - [26/Oct/2022:01:01:35 +0000] "GET / HTTP/1.1" 200 14 "-" "Amazon CloudFront"
10.0.1.134 - - [26/Oct/2022:01:01:37 +0000] "GET / HTTP/1.1" 200 14 "-" "ELB-HealthChecker/2.0"
10.0.1.134 - - [26/Oct/2022:01:01:43 +0000] "GET / HTTP/1.1" 200 14 "-" "Amazon CloudFront"
10.0.0.225 - - [26/Oct/2022:01:01:43 +0000] "GET / HTTP/1.1" 200 14 "-" "ELB-HealthChecker/2.0"
10.0.1.134 - - [26/Oct/2022:01:01:47 +0000] "GET / HTTP/1.1" 200 14 "-" "ELB-HealthChecker/2.0"

やはりこれは最初のリクエストから数秒を待機時間としているようです。待機時間が終わったら全てオリジンリクエストされるのでしょうか。
次は 10 秒かけて 10 件のリクエストを送信してみます。
JMeter ではだいたい 1 秒に 1 回リクエストが送信されるはずです。

10.0.0.225 - - [26/Oct/2022:01:05:03 +0000] "GET / HTTP/1.1" 200 14 "-" "ELB-HealthChecker/2.0"
10.0.1.134 - - [26/Oct/2022:01:05:07 +0000] "GET / HTTP/1.1" 200 14 "-" "ELB-HealthChecker/2.0"
10.0.0.225 - - [26/Oct/2022:01:05:13 +0000] "GET / HTTP/1.1" 200 14 "-" "ELB-HealthChecker/2.0"
10.0.1.134 - - [26/Oct/2022:01:05:17 +0000] "GET / HTTP/1.1" 200 14 "-" "ELB-HealthChecker/2.0"
10.0.1.134 - - [26/Oct/2022:01:05:23 +0000] "GET / HTTP/1.1" 200 14 "-" "Amazon CloudFront"
10.0.0.225 - - [26/Oct/2022:01:05:23 +0000] "GET / HTTP/1.1" 200 14 "-" "ELB-HealthChecker/2.0"
10.0.1.134 - - [26/Oct/2022:01:05:27 +0000] "GET / HTTP/1.1" 200 14 "-" "ELB-HealthChecker/2.0"
10.0.0.225 - - [26/Oct/2022:01:05:29 +0000] "GET / HTTP/1.1" 200 14 "-" "Amazon CloudFront"
10.0.0.225 - - [26/Oct/2022:01:05:33 +0000] "GET / HTTP/1.1" 200 14 "-" "ELB-HealthChecker/2.0"
10.0.1.134 - - [26/Oct/2022:01:05:37 +0000] "GET / HTTP/1.1" 200 14 "-" "ELB-HealthChecker/2.0"
10.0.0.225 - - [26/Oct/2022:01:05:43 +0000] "GET / HTTP/1.1" 200 14 "-" "ELB-HealthChecker/2.0"

結果としては折りたたみが 2 回発生しました。
0 ~ 4 秒のリクエストが折りたたまれています。さらに 5 ~ 9 秒のリクエストも折りたたまれています。発生したオリジンリクエストは 2 回です。

なるほど。

まとめ

本日は Amazon CloudFront の Request Collapsing (リクエストの折りたたみ)で仕様とされている「短時間」について検証しました。

数回検証した結果から、折りたたみ時の短時間の一時停止はキャッシュがない状態で受け取った最初のリクエストからだいたい 5 秒間だということがわかりました。
その 5 秒間で集中的にリクエストが発生したとしてもオリジンへ発生するリクエストは（同一キャッシュキーごとに）1 回ということですね。

さらに、折りたたみの範囲が終わったあとはまたオリジンへのリクエストが必要か評価されるのですが、その時点でキャッシュがまだ存在していない場合はまたそこから 5 秒間は折りたたみの対象として待機してくれる仕組みのようです。