CloudWatch LogsInsightsでLambdaの速度を計測してみよう #lambda

隙あらばCloudWatch LogsInsightsで速度集計したりしています。（自己紹介）

本記事はCloudWatch LogsInsightsでやってみよう記事第2弾です。前回の記事はこちら。

第2弾としてLambdaの速度計測をします。

Lambdaのログの基本（デフォルトの設定の場合）と余談

私自身、Lambdaに出力されるログをいじったことがないので、そもそもデフォルト以外のログが存在するのか把握しておりません。
Lambda関数内でログを仕込んでおけば話は別ですが。

CloudWatch Logs上には /aws/lambda/$Lambda関数名 といったロググループで出力されます。
そしてログの中身としてはこのようになります。 $ の部分は適宜置き換えて読んでください。

START RequestId: $request_id Version: $$version
END RequestId: $request_id
REPORT RequestId: $request_id   Duration: $duration_time(小数点2桁まで) ms    Billed Duration: $duration_time(小数点切り上げ) ms   Memory Size: $memory_size MB    Max Memory Used: $used_memory_size MB   Init Duration: $init_duration_time ms

この中のDurationが処理時間、BilledDurationが課金対象となる時間です。
1ms単位での課金となっているために、小数点が切り上げられているわけですね。

Memory Size は関数に割り当てているメモリ、 Max Memory Used が実際に使われたメモリです。
この差分が大きいほどメモリを持て余していると言えますが、メモリに比例してCPUも増強されるので速度目的で多めに設定していることもあります。
なので持て余しているからといって一概に削減できるわけではない点に注意が必要です。

最後に表示されている Init Duration がいわゆるコールドスタートにかかっている時間です。
こちらは表示されるときとされないときがあります。
理由としては、LambdaではInitというフェーズでコンテナの初期化（ランタイムの準備など）をおこないます。
一度Lambdaが起動すればある程度の時間はそのコンテナが生きているため使い回すことでInitは発生しませんが、
ある程度の時間が経過するとコンテナが破棄されてしまい、またInitが発生するようになります。
なのでこれが表示されているということは初期化が発生しているということになります。

そこらへんの話は公式ドキュメントやKeisuke69さんのブログ記事を読むと理解が捗ると思います。

https://docs.aws.amazon.com/ja_jp/lambda/latest/dg/runtimes-context.html
https://www.keisuke69.net/entry/2020/09/29/131203

API Gatewayを使ってWebアプリケーションからLambda関数を実行しているようなケースではなかなか馬鹿にできない時間がかかるので、対策を打っていきたいところですね。
対策については今回話したいことの本筋から外れるので省略します。classmethodさんの記事などが参考になりますのでそちらをご参照ください。

本題

さて本題です。
なんとCloudWatch LogsInsightsでLambdaのログを集計しようとするとデフォルトでこれらのフィールドが用意されています。

@ingestionTime
@logStream
@message
@requestId
@timestamp
@type
@billedDuration
@duration
@initDuration
@maxMemoryUsed
@memorySize

つまり自分でこれらの値を parse @message "Duration: * ms" as duration_time みたいにパースすることなく使えます。超便利ですね。

Lambda関数の実行時間を集計する

filter @type = "REPORT"
| stats count(*) as `count`,
  pct(@duration, 95) as pct95,
  pct(@duration, 50) as pct50,
  avg(@duration) as average

count	pct95	pct50	average
14	194.26	153.43	153.135

簡単に実行回数、95パーセンタイル、中央値、平均値が出せましたね。
このクエリで解説が必要そうな点は2つでしょうか。

1つは filter @type = "REPORT" で @duration が存在するログのみを集計している点です。
前述のようにログの中には @type が START や END のものもあります。
当然そういったログも集計対象になるので除外してあげる必要があります。
（自前でログを仕込んだ場合に何になるんでしょうね）

もう1つは as `count`ですね。
Insightsのクエリで関数名と同じエイリアス名をつけたい場合はバッククォートでつけれるようです。
余談ですが # でクエリのコメントアウトもできます。ちょっとクエリを変えて試したいときにどうぞ。

Duration time を集計することは純粋に関数だけの処理時間を集計するということなので、例えばAPI Gatewayに対して curl などをしてレスポンスが得られるまでの速度との差分を求めれば、ネットワークの問題なのか、関数側の問題なのかの切り分けにも役立ちます。
またメモリを増量してどれだけ速度が改善するのかというのもネットワークの影響なしに正確に測ることができると思います。
（というか私の部署はこれでメモリの選定をしました）

コールドスタートの割合や時間を集計する

実行時間と同じ感じで集計可能です。

filter @type = "REPORT"
| stats count(@initDuration) as `init_count`,
  count(@duration) as `all_count`,
  pct(@initDuration, 95) as pct95,
  pct(@initDuration, 50) as pct50,
  avg(@initDuration) as average
| display init_count, all_count, concat(((init_count/all_count)*100), "%") as ratio, pct95, pct50, average

init_count	all_count	ratio	pct95	pct50	average
7	14	50.0%	707.01	697.61	695.5714

今回のポイントとしては3つ。
まず1つに、それぞれ @initDuration と @duration で数を集計します。これにより、コールドスタートが発生した回数とコールドスタートに関係なく関数の実行回数が出せます。
2つ目にそれをそのまま表示するだけでなく、どれくらいの割合で発生しているか、も知りたいところなのではないかと思います。
ですので stats でそのまま使うのではなく display で計算した結果を使うようにしています。

最後に、これは賛否あると思いますがratioに単位を付与するために concat 関数を使っています。
これにより文字列結合ができて単位が分かりやすいですね。

データの方に余計な文字列を入れるのを好まない場合はラベル側につけてあげれば良いですね。ここはお好みで。

init_count	all_count	ratio(%)	pct95(ms)	pct50(ms)	average(ms)
7	14	50.0	707.01	697.61	695.5714

こうすることでコールドスタートが許容できる速度、回数なのかの判断材料が出せるわけです。

ググってたら外国のブログだったかどこかで「初期化にかかる時間はAWS X-rayを使わないと出せない」なんて書かれていましたが、そんなことはありませんでした。
（もしかしたらX-rayのほうがより詳細な数字が出せるのかもしれませんが…）

終わりに

ひとまずお手軽に速度計測を試すにはCloudWatch LogsInsightsで十分なのではないかな、と思います。
Lambdaを使っている皆様はぜひ試してみてください。