東京リージョンでVPC Lambdaの高速起動が確認できたので改善効果を計測してみた

CX事業本部＠大阪の岩田です。

先日公式にアナウンスされたVPC Lambdaのコールドスタート改善、数ヶ月かけて徐々に適用とのことでしたが、先ほど東京リージョンで新アーキテクチャでのVPC Lambda起動が確認できました。 【速報】もうアンチパターンとは呼ばせない！！VPC Lambdaのコールドスタート改善が正式アナウンスされました！！

VPC Lambdaのコールドスタートがどの程度改善されたのか、早速計測してみたいと思います。

新アーキテクチャでの起動を確認する

先日のVPC Lambda改善のアナウンス以降毎日VPC Lambda関連のリソース(VPC,サブネット,SG,Lambda...)を作成するCFnスタックを作成して動作の変化をチェックしていました。 いつものようにスタックを作成してENIの状況をチェックしてみます。

CFnのスタック作成だけでENIが作成されました。旧アーキテクチャでは実際にLambdaを実行するまでENIは作成されなかったので、新アーキテクチャが適用されていそうです。実はVPC Lambda改善のアナウンス直後から東京リージョンではこのような挙動が確認できていました。が、この後実際にLambdaを実行すると事前作成したENIが利用されず新たにENIが作成され、結果として起動が遅いという状態が続いていました。新アーキテクチャと旧アーキテクチャが混在しているような状態です。

今日もいつものようにテストイベントを実行して確認してみました。すると...は、早い！！すぐに実行が完了しました。X-rayのトレース結果を確認します。

所要時間なんと411msです!! 念のためENIの状況を確認しましたが、ENIの追加作成は行われていませんでした。事前作成したENIを使うという新アーキテクチャが適用されていることが分かります。

計測してみる

実際にどの程度改善しているのか試してみます。 計測の方法は色々考えられるのですが、取り急ぎ過去のブログで計測した時と同じ方法でやってみます。

VPC Lambdaのコールドスタートにお悩みの方へ捧ぐコールドスタート予防のハック Lambdaを定期実行するならメモリの割り当ては1600Mがオススメ？！

こちらのブログで紹介した方法を使って、メモリを128M割り当てたVPC Lambdaに対して50並列でのアクセスを行い、応答時間を確認してみます、

hey -n 500 -c 50 https://xxxxxxxxxx.execute-api.ap-northeast-1.amazonaws.com/Stage/test

2019/5/29のブログ執筆時点での結果は下記の通りでした

Summary:
  Total:  13.4614 secs
  Slowest:  13.0460 secs
  Fastest:  0.0194 secs
  Average:  1.2528 secs
  Requests/sec: 37.1433
 
  Total data: 2500 bytes
  Size/request: 5 bytes
 
Response time histogram:
  0.019 [1] |
  1.322 [448] |■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■
  2.625 [1] |
  3.927 [0] |
  5.230 [0] |
  6.533 [0] |
  7.835 [0] |
  9.138 [0] |
  10.441 [4]  |
  11.743 [9]  |■
  13.046 [37] |■■■
 
 
Latency distribution:
  10% in 0.0329 secs
  25% in 0.0388 secs
  50% in 0.0454 secs
  75% in 0.0613 secs
  90% in 10.1785 secs
  95% in 12.2642 secs
  99% in 12.8836 secs
 
Details (average, fastest, slowest):
  DNS+dialup: 0.0087 secs, 0.0194 secs, 13.0460 secs
  DNS-lookup: 0.0051 secs, 0.0000 secs, 0.0520 secs
  req write:  0.0000 secs, 0.0000 secs, 0.0009 secs
  resp wait:  1.2440 secs, 0.0193 secs, 12.9546 secs
  resp read:  0.0000 secs, 0.0000 secs, 0.0007 secs
 
Status code distribution:
  [200] 500 responses

新アーキテクチャが適用されていそうな本日、改めて実行した結果です

Summary:
  Total:	20.2692 secs
  Slowest:	12.2315 secs
  Fastest:	0.0220 secs
  Average:	0.6355 secs
  Requests/sec:	24.6680

  Total data:	2370 bytes
  Size/request:	5 bytes

Response time histogram:
  0.022 [1]	|
  1.243 [451]	|■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■
  2.464 [0]	|
  3.685 [0]	|
  4.906 [0]	|
  6.127 [0]	|
  7.348 [0]	|
  8.569 [0]	|
  9.790 [2]	|
  11.011 [3]	|
  12.232 [17]	|■■


Latency distribution:
  10% in 0.0351 secs
  25% in 0.0410 secs
  50% in 0.0569 secs
  75% in 0.0784 secs
  90% in 0.4862 secs
  95% in 0.5759 secs
  99% in 12.1834 secs

Details (average, fastest, slowest):
  DNS+dialup:	0.0156 secs, 0.0220 secs, 12.2315 secs
  DNS-lookup:	0.0054 secs, 0.0000 secs, 0.0361 secs
  req write:	0.0003 secs, 0.0000 secs, 0.0058 secs
  resp wait:	0.6196 secs, 0.0220 secs, 12.1197 secs
  resp read:	0.0000 secs, 0.0000 secs, 0.0001 secs

Status code distribution:
  [200]	474 responses

Error distribution:
  [26]	Get https://xxxxxxxxx.execute-api.ap-northeast-1.amazonaws.com/Stage/test: net/http: request canceled (Client.Timeout exceeded while awaiting headers)

残念ながら22/500回で大きな遅延が発生、さらに26/500は hey コマンドがタイムアウトしてしまいました。( -t 0 オプションを付けておけば良かった...)2019/5/29時点の実行結果と似たような結果になってしまいました。

ENIの状況を確認すると、追加で2つのENIが作成されていました。

新アーキテクチャの実力はこんなものなのでしょうか？？

VPC Lambdaへのアクセス並列度を徐々に上げていった場合

色々と試行錯誤しつつ挙動を観察した結果、どうもVPC Lambdaの同時実行数が増えた場合にENIを追加作成してスケールアウトさせるような動きをしており、ENI追加作成の遅延を引いてしまっているように見えます。多分。

先ほどの計測では1気に50並列の計測を行ったので、並列度を徐々に上げながら再度計測してみます。途中で何度かENIの追加作成が走ったので手動によるENIのデタッチ＆削除を交えつつ良い結果が出るように無理矢理調整しながら計測してみました

最終的にこんな結果を出すことに成功しました。事前作成されたENIが1つしか存在しない状態で100並列でAPI GW経由でVPC Lambdaを起動させています

hey -n 500 -c 100 https://xxxxxx.execute-api.ap-northeast-1.amazonaws.com/Stage/test

Summary:
  Total:	0.4281 secs
  Slowest:	0.1542 secs
  Fastest:	0.0219 secs
  Average:	0.0632 secs
  Requests/sec:	1167.8686

  Total data:	2500 bytes
  Size/request:	5 bytes

Response time histogram:
  0.022 [1]	|
  0.035 [59]	|■■■■■■■■■■■■■■■■
  0.048 [149]	|■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■
  0.062 [102]	|■■■■■■■■■■■■■■■■■■■■■■■■■■■
  0.075 [62]	|■■■■■■■■■■■■■■■■■
  0.088 [35]	|■■■■■■■■■
  0.101 [23]	|■■■■■■
  0.115 [13]	|■■■
  0.128 [20]	|■■■■■
  0.141 [24]	|■■■■■■
  0.154 [12]	|■■■


Latency distribution:
  10% in 0.0339 secs
  25% in 0.0404 secs
  50% in 0.0526 secs
  75% in 0.0754 secs
  90% in 0.1180 secs
  95% in 0.1353 secs
  99% in 0.1498 secs

Details (average, fastest, slowest):
  DNS+dialup:	0.0090 secs, 0.0219 secs, 0.1542 secs
  DNS-lookup:	0.0005 secs, 0.0000 secs, 0.0136 secs
  req write:	0.0002 secs, 0.0000 secs, 0.0094 secs
  resp wait:	0.0506 secs, 0.0218 secs, 0.1164 secs
  resp read:	0.0000 secs, 0.0000 secs, 0.0039 secs

Status code distribution:
  [200]	500 responses

計測方法はかなり無理矢理ですが、ENI1つで100並列を処理しつつも大きな遅延が発生しない計測結果を得ることができました。ちょっとずつ並列度を上げていったり、ENI作成が走った場合はENIをデタッチ&削除して再計測しているので、恐らく上記の計測結果に関して全てウォームスタートを引いており、ENI作成を伴わないコールドスタートも引いていないと思われます。

上記の計測結果は恣意的に良い結果を出しに行ったので実際のワークロードではこんなに良い結果は出ないはずです。あくまでVPC Lambda改善の適用状況を妄想するためのネタとして参考にするに留めて下さい

まとめ

新アーキテクチャでのVPC Lambdaの挙動を観察してみました。期待していたほどの結果は出ませんでしたが、そもそも新アーキテクチャへの移行は徐々に段階的に実施されるとのことで、現状AWSからは移行完了のアナウンスが出ていません。バージニア等のリージョンでは未だにENIの事前作成が行われない状態です。

繰り返しになりますが、今回の計測結果は、あくまでも段階移行の過程における一時的な計測結果として参考にするに留めて下さい。AWSからの移行完了のアナウンスが出た後に、改めて同様の計測を試したいと思います。また、移行完了のアナウンスを待たずにもっと色々なパターンを試してみるつもりなので、今後のブログにもご期待ください！！