Provisioned Concurrencyで予約したLambda実行環境が初期化されるまでの時間を計測してみた #reinvent

AWS re:Invent 2019

#サーバーレス

#AWS Lambda

#AWS

岩田智哉

2019.12.10

この記事は公開されてから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を指定

少し時間が経過すると...

Provisioned Concurrencyで指定した同時実行数の一部がプロビジョニング完了

425/900まで進んできました。さらにこのまましばらく待つと...

Provisioned Concurrencyで指定した同時実行数が全てプロビジョニング完了

ステータスが準備完了になりました。ちなみにCloudTrailのログはこんな感じでした。

Provisioned Concurrency設定直後の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件は一体何なんでしょうか...また今度もうちょっと色々試してみようと思います。ひとまず今日のところは以上となります。