NODE_OPTIONS=–enable-source-mapsを有効化したらLambdaのコールドスタートが1.5秒から5.3秒まで悪化した話

NODE_OPTIONS=--enable-source-mapsはトレードオフを理解した上で利用を検討しましょう

#AWS Lambda

#Node.js

#AWS

岩田智哉

2022.03.05

この記事は公開されてから1年以上経過しています。情報が古い可能性がありますので、ご注意ください。

MAD事業部@大阪の岩田です。

今関わっている案件はTypeScritptで開発したコードをLambdaのNode.js14x環境にデプロイして利用しています。先日全てのLambdaのパフォーマンスが異様に遅くなる現象に遭遇したのですが、調査したところLambdaの環境変数NODE_OPTIONSに--enable-source-mapsの指定を追加したことが原因でした。この環境変数は便利な機能ではありますが、パフォーマンスへの悪影響も大きいので、利用する際はしっかりパフォーマンスへのインパクトを計測して判断するようにしましょう。

環境

今回問題が発生したのは以下の環境です

Lambdaのランタイム: Node.js 14.x
Lambdaのメモリ割り当ては1769MB
TypeScript: 4.4
Lambdaレイヤーのサイズ:
- 圧縮状態で10M
- 解凍後は48M
- レイヤーの中身はnpm installしたnode_modulesから*.mdファイルや*.d.tsファイルを削除してスリム化したものです。つまり外部のライブラリはバンドルファイルに含めない構成で、ソースマップに関してもノータッチです
Lambda Functionのサイズ
- 圧縮状態で約100K
- 解凍後は約500K
- ソースマップはインライン形式で埋め込み

システムの構成はよくあるSPA & REST APIのバックエンドAPIという構成で、API GWの背後でLambdaを動かしています。

どうやって気づいたか？

テスト環境で一連の動作を確認していたところAPIのレスポンスが異様に遅いことに気付きました。いちいち計測しなくても体感で分かるレベルです。特に一定時間を開けた空けた後など、コールドスタートを引いたと思われる際のレスポンスの悪化が顕著でした。以前コールドスタートの時間を確認した際は1.5秒程度で起動できていたのですが、普通に5秒以上はかかってそうな感覚でした。以前は問題ないレベルだったことが確認できているので、どこかのタイミングでパフォーマンスに悪影響を与える変更が発生していそうです。

CloudWatch Logsのログを分析してみる

DevOps Guruを使っていれば簡単に気づけたのかもしれないですが、DevOps Guruは利用していなかったので、CloudWatch Logsのログを分析してみます。

CloudWatch Logs Insightsから以下のクエリを実行し、1時間ごとにコールドスタートの所要時間を集計します

filter @type = "REPORT" |
parse @message /Init Duration: (?<init>\S+)/ |
stats avg(init) as avg by bin(1h) as time |
sort time|
limit 100

結果は以下のようになりました。時刻はUTCなので、3/2の11時台からコールドスタートの所要時間が大きく悪化していることが分かります。

time	avg
2022-03-01 22:00:00.000	1467.94
2022-03-01 23:00:00.000	1474.3043
2022-03-02 00:00:00.000	1517.51
2022-03-02 01:00:00.000	1644.53
2022-03-02 02:00:00.000	6333.58
2022-03-02 03:00:00.000	6357.386
2022-03-02 04:00:00.000	6895.1
2022-03-02 05:00:00.000	6467.8075

この情報を元に3/2の11時頃に実施されたデプロイに含まれるコミットを辿っていくと...CDKのコードに以下のコードが追加されていることが分かりました。

environment: {
...略
+        NODE_OPTIONS: '--enable-source-maps',

NODE_OPTIONSに--enable-source-mapsを指定した際のパフォーマンスに対する悪影響について調べてみると以下のような情報がヒットしました。ソースマップが原因と考えて良さそうです。

https://github.com/nodejs/node/issues/41541#issuecomment-1054819509

ソースマップ有効化前後の比較

これで原因がはっきりしたのでソースマップが有効化される前後でのLambdaのパフォーマンスについてもう少し分析してみます。

今度は以下のクエリを実行し、コールドスタート時の初期化処理に要した時間の

発生回数
最小値
最大値
平均値
中央値
95%タイル

を計測します

filter @type = "REPORT" |
parse @message /Init Duration: (?<init>\S+)/ |
stats count(init) as count, min(init) as min,max(init) as max, avg(init) as avg, median(init) as median, pct(init, 95) as tile

このクエリをソースマップ有効化前の3/1のログ、ソースマップ有効化後の3/3のログに対して実行し、結果を集計します。

なお、計測対象のLambdaがコールドスタート時に実施している処理はTypeScriptのコードでいうと

import {} from...

といったimport処理に加えてAWS SDK for JavaScript v3のSecretsManagerClientクラスのインスタンス作成を実行しており、AWSサービスとの通信のようなオーバーヘッドの大きな処理は実行していません。また3/1~3/3の間にロジックの修正は入ってません。

集計結果は以下の通りです。

集計対象日	件数	最小値	最大値	平均値	中央値	95%タイル
3/1	27	1316.61	2342.76	1491.0641	1420	2078.34
3/3	19	4527.64	5859.52	5353.4305	5355.7	5859.52

ちょっと件数が少ないですが、それでもソースマップ有効化前後に圧倒的に遅くなっていることが分かります。実装の内容次第で悪影響の度合いは変わって来ますが、今回のケースに関していうとNODE_OPTIONSに--enable-source-mapsを設定するオーバーヘッドは無視できないレベルと言えるでしょう。

まとめ

実際にどの程度の悪影響が出るかはLambdaの実装や利用しているライブラリに依存するので、上記の結果はあくまで参考値となります。数秒レベルで悪影響が発生するケースもあるという参考にして頂き、自身の環境でNODE_OPTIONSに--enable-source-mapsを設定すべきかどうかは実際に計測を行いながら検討して頂くようお願いします。