この記事は公開されてから1年以上経過しています。情報が古い可能性がありますので、ご注意ください。
CX事業本部＠大阪の岩田です。 この記事はAWS LambdaとServerless #1 Advent Calendar 2019の10日目 です
はじめに
re:invent2019でLambdaの新しい機能としてProvisioned Concurrencyの設定が発表されました。設定した数だけ事前にLambda実行環境をプロビジョニングしておけるこの機能、ドキュメントによると設定から数分でLambda実行環境のプロビジョニングが完了するそうです。
After a couple of minutes, Lambda allocates provisioned concurrency at the same rate that a function scales under load
実際この数分というのはどの程度なのでしょう？2~3分？それとも5分？ということで実際に試してみました。
環境
今回検証に利用した環境です
- リージョン: オハイオ
- Lambdaのランタイム: Node.js 12.x
やること
まず以下のコードを準備します。
const now = new Date();
console.log(now.toISOString(), now.getTime());
exports.handler = async (event) => {
// TODO implement
const response = {
statusCode: 200,
body: JSON.stringify('Hello from Lambda!'),
};
return response;
};デフォルトのHello Worldのコードにhandler外のログ出力を追加しただけのコードです。これでLambda実行環境が初期化されたタイミングでCloudWatch Logsに初期化が実行された日時が出力されます。人が目で見やすいようにISO形式、後で集計しやすいようにUnixタイム形式でそれぞれログを出力します。ログのサンプルはこんな感じです。
2019-12-09T05:26:59.801Z undefined INFO 2019-12-09T05:26:59.801Z 1575869219801よく考えたらISO形式のログは標準で出力されるので不要でした。。このLambdaのコードから新しいバージョンを発行し、発行されたバージョンにProvisioned Concurrencyを設定、ステータスが準備完了になった時点でCloudWatch Logsに出力されたログを分析してみます。なお同時実行数にはMaxの900を指定します。
やってみる
早速やってみます。まずはProvisioned Concurrencyに900を指定
少し時間が経過すると...
425/900まで進んできました。さらにこのまましばらく待つと...
ステータスが準備完了になりました。ちなみにCloudTrailのログはこんな感じでした。
UTCの5:22:24にPutProvisionedConcurrencyConfigというイベントのログが出力されているので、この日時とLambdaがCloudWatch Logsに出力したログを見比べれば色々分析できそうです。
分析
CloudWatch Logsのログをエクスポートして、色々分析してみます。
ログの件数
同時実行数に900を指定したのでLambda実行環境は900個初期化され、900件のログが出力されているはずです。が、なんとログの件数は1398件でした！！差分の498件は一体何なんでしょうか？？一旦ガツンと同時実行数を確保した後で余分なLambda実行環境を停止させて、最終的な同時実行数を調整してるんでしょうか？
設定完了 ~ 1件目のログが出力されるまでの時間
1件目のログは12,801ミリ秒後に出力されていました。
設定完了 ~ 最後のログが出力されるまでの時間
1398件目のログは275,801ミリ秒後に出力されていました。約4.5分後です。
設定完了 ~ ログが出力されるまでの平均時間
平均すると61,705ミリ秒後にログが出力されていました。約1分後ですね
設定完了 ~ ログが出力されるまでの標準偏差
EXCELのSTDEV.Pで標準偏差を計算しました。標準偏差(STDEV.P)は約33,160でした。
結果まとめ
表にまとめるとこんな感じでした
| 指標 | 結果(ミリ秒) |
|---|---|
| 最小値 | 12,801 |
| 最大値 | 275,801 |
| 平均 | 61,705 |
| 標準偏差(STDEV.P) | 33,160.96903 |
まとめ
１回しか計測できていませんが、Provisioned Concurrencyの設定完了後、約4.5分で指定した同時実行数の分だけLambda実行環境の初期化が完了することが確認できました。それにしてもログの差分498件は一体何なんでしょうか...また今度もうちょっと色々試してみようと思います。ひとまず今日のところは以上となります。
2
