エヌデーデーのジョン ミンソです。
今回が初めての投稿となります。普段はAWSを活用して、様々なシステム開発に携わっているエンジニアです。
1. はじめに
近年、クラウドサービスの普及により、サーバーを管理せずにシステムを構築できる「サーバーレス構成」が、さまざまなシステムやアプリの開発で広く採用されるようになりました。
中でもAWS LambdaとDynamoDBの組み合わせは手軽に始められる一方で、「APIへの初回リクエストだけ、なぜか応答が遅い」という悩みに直面したことがある方も多いのではないでしょうか。
私自身も、AWS LambdaとDynamoDBを活用したシステムを開発する中で、この現象に直面しました。2回目以降は約0.2秒で応答が返ってくるAPIが、初回だけは約5秒もかかっていたのです。
本記事では、この「コールドスタート」による初回遅延について、CloudWatch Logsを使って原因を特定し、改善するまでの過程をご紹介します。
既存のシステムでは、応答までに約5秒ほどかかっていました。一方で、続けて同じAPIを呼び出すと、約0.2秒で応答が返ってくることを確認しました。
当初は、AWS Lambdaのコールドスタート（Cold Start）が原因ではないかと考えました。
しかし、コールドスタートが発生しているという事実だけでは、実際にどの処理で遅延が発生しているのかを特定することはできませんでした。
そこで今回は、単純にメモリを増やしたりコードを変更したりするのではなく、CloudWatch Logsを活用して各処理の実行時間を段階別に計測し、ボトルネックを特定したうえで、性能改善に取り組むことにしました。
2. システム構成と問題の再現
2.1 システム構成
調査対象は、ReactのフロントエンドとAWS Lambda、DynamoDBで構成されたサーバーレスWebアプリケーションです。
ユーザーがログイン後、初めてメイン画面にアクセスすると、API Gatewayを経由してLambda関数が実行されます。
LambdaはDynamoDBからデータを取得し、レスポンスを生成します。
使用技術は以下のとおりです。
| 区分 | 使用技術 |
|---|---|
| フロントエンド | React |
| API | Amazon API Gateway |
| バックエンド | AWS Lambda (Python 3.12) |
| データベース | Amazon DynamoDB |
| AWS SDK | Boto3 |
| ログ・性能分析 | Amazon CloudWatch Logs |
| 調査対象API | GET /calendar |
2.2 問題の再現
GET /calendar APIを呼び出し、CloudWatch Logsを確認したところ、コールドスタートとウォームスタートの間に大きな性能差が見られました。
以下は、Lambdaのメモリを128MBに設定した際の測定結果です。
| 測定項目 | コールドスタート | ウォームスタート |
|---|---|---|
| Handler Duration（PythonのHandler実行時間） | 2,908.06ms | 204.63ms |
| Init Duration（Lambda実行環境の初期化時間） | 761.76ms | なし |
| Billed Duration（課金対象時間） | 3,670ms | 205ms |
コールドスタートではLambdaが新しい実行環境を準備する必要がありますが、ウォームスタートでは既存の実行環境を再利用できます。
しかし、今回のログで確認できたInit Durationは約762msでした。
一方、Handlerの実行には約2.9秒かかっていました。
つまり、コールドスタート時の遅延は、Lambda実行環境の初期化だけでなく、Handler内部のPythonアプリケーション処理にも発生していることが分かりました。
そのため、Lambdaのランタイム初期化以外にも、アプリケーション内部にボトルネックが存在する可能性があると考え、処理時間をさらに詳しく調査することにしました。
3. 原因分析のためのログ確認
3.1 初期の性能ログ分析
既存のシステムでは、主要な処理ごとの実行時間を記録するために、[PERF]ログを使用していました。
ログを確認したところ、特に以下の処理で多くの時間がかかっていることが分かりました。
[PERF] route=GET /calendar<br>step=initialize_dynamodb<br>duration_ms=2297.5<br><br>
[PERF] route=GET /calendar<br>step=get_current_user<br>duration_ms=306.6<br><br>
[PERF] route=GET /calendar<br>step=query_calendar<br>duration_ms=41.6<br><br>
[PERF] route=GET /calendar<br>step=total<br>duration_ms=2994.9ここで、initialize_dynamodbの処理に約2.3秒かかっていることが確認できました。
一方、実際にDynamoDBからデータを取得するquery_calendarの処理時間は約42msでした。
この結果から、以下の2つの仮説を立てました。
仮説1： DynamoDBのデータ取得処理そのものよりも、AWS SDKであるBoto3の初期化処理が、全体の実行時間に大きく影響しているのではないか。
仮説2： AWS Lambdaでは、メモリ設定に応じて割り当てられるCPUリソースも変化するため、メモリを増やすことでBoto3の初期化時間を短縮できるのではないか。
ただし、既存のログでは初期化処理全体の実行時間しか確認できなかったため、具体的にどの処理で遅延が発生しているのか、さらに詳しく調査する必要がありました。
4. 性能計測範囲の拡張
4.1 ログ仕様書の修正
前述の調査では、initialize_dynamodbの処理に約2.3秒かかっていることが確認できました。
しかし、既存のログではDynamoDBの初期化処理全体の実行時間しか確認できず、具体的にどの処理がボトルネックとなっているのかを特定することはできませんでした。
そこで、より詳細な原因分析を行うため、既存のログ仕様書を修正し、DynamoDB初期化処理の内部計測を追加しました。
今回のログ追加では、以下の2点を目的としました。
- 各処理にどの程度の時間がかかっているのかを確認できること
- 1リクエストあたりのLambda全体の処理時間を確認できること
計測方法については、以下のように定義しました。
各処理の開始直前に開始時刻を記録し、処理終了直後に経過時間をログとして出力する。
この方針に基づいてログ仕様書を修正し、処理ごとの実行時間をより詳細に確認できるようにしました。
4.2 DynamoDB初期化処理の詳細計測
今回の変更では、GET /calendarの既存のinitialize_dynamodbログを維持したまま、内部処理をさらに細分化して計測できるようにしました。
ログの出力形式についても、既存の[PERF]形式をそのまま使用しています。
[PERF] route=GET /calendar step=<step> duration_ms=<小数第1位></code>また、各ログは共有DynamoDB Resourceが初めて生成される際にのみ出力されるようにしています。
追加した計測項目は以下のとおりです。
| step | 計測対象・処理内容 |
|---|---|
dynamodb_prepare_session | Boto3のデフォルトSessionの準備。Sessionが存在しない場合は、その生成やSDKの初期設定も含む |
dynamodb_load_resource_model | DynamoDBのResource定義モデル（resources-1）の検索・読み込み・解析 |
dynamodb_load_service_model | DynamoDBのAPI定義モデル（service-2）の検索・読み込み・解析 |
dynamodb_load_endpoint_rules | 接続先を決定するためのEndpoint Rulesモデル（endpoint-rule-set-1）の読み込み |
dynamodb_load_other_model | その他のSDKモデルの読み込み。呼び出しごとに個別に記録 |
dynamodb_resolve_credentials | Botocoreによる認証情報の取得。環境変数などからの認証情報の探索、またはキャッシュの参照 |
dynamodb_create_client | 低レベルClient生成処理全体。APIモデル・Endpoint Rules・認証情報の取得、イベント処理、HTTPセッションの設定などを含む |
dynamodb_create_resource_class | Resourceクラスの生成およびイベント処理。DynamoDBのデータ変換処理や関連モジュールの遅延読み込みが含まれる場合がある |
※ dynamodb_load_service_modelやdynamodb_load_endpoint_rulesなどの処理時間は、dynamodb_create_clientの計測時間に含まれる場合があるため、単純に合計しないようにしています。
4.3 Boto3の初期化処理について
ここで、今回の調査に関係するBoto3の仕組みについて簡単に説明します。
Boto3は、PythonからAWSの各種サービスを操作するための公式SDK（Software Development Kit）です。
今回の調査で登場する主な要素は、以下のとおりです。
| 項目 | 役割 |
|---|---|
| Session | AWSの認証情報やリージョンなどの設定を管理する |
| Client | DynamoDBのAPIを呼び出すための低レベルインターフェース |
| Resource | Clientを利用してAWSサービスをより簡単に操作するための高レベルインターフェース |
| Service Model | DynamoDBが提供するAPIの種類やリクエスト・レスポンスの構造を定義する |
| Endpoint Rules | リージョンや設定に応じて、APIリクエストの送信先を決定するためのルール |
重要なのは、これらの初期化処理と、実際にDynamoDBからデータを取得する処理は別であるという点です。
例えば、DynamoDB Clientの生成は、APIを呼び出すための設定や内部オブジェクトを準備する処理であり、Clientを生成しただけでDynamoDBへのデータ取得リクエストが発生するわけではありません。
実際のデータ取得は、GetItemやQueryなどのAPIを呼び出した際に行われます。
今回のログ計測では、こうしたSDK内部の初期化処理にどの程度の時間がかかっているのかを確認し、遅延の原因をさらに詳しく分析することを目的としました。
5. メモリ設定別の性能比較
5.1 検証方法
Boto3の初期化処理がCPUリソースの影響を受けているかを確認するため、AWS Lambdaのメモリ設定を変更しながら性能を比較しました。
メモリ設定は、128MB、256MB、512MBの3パターンとしました。
同じGET /calendar APIを使用し、それぞれの設定でコールドスタートとウォームスタートの実行時間を計測しました。
コールドスタートが発生しているかどうかは、CloudWatch LogsのINIT_STARTおよびREPORTログをもとに確認しました。
また、512MBまで測定した後、再び128MBに設定を戻し、同様の性能低下が再現されるかについても確認しました。
なお、今回の検証は各条件につき1回ずつ測定した小規模な比較です。そのため、統計的に有意な性能差や、実際の運用環境における平均応答時間を確定するものではありません。
5.2 Handler実行時間の比較
| メモリ設定 | コールドスタート | ウォームスタート |
|---|---|---|
| 128MB | 2,908.06ms | 204.63ms |
| 256MB | 1,419.54ms | 93.55ms |
| 512MB | 696.56ms | 42.86ms |
メモリ設定を増やすほど、実行時間が短縮される傾向が見られました。
128MBと512MBを比較すると、コールドスタート時のHandler実行時間は約76％短縮されました。
ウォームスタートでも同様の傾向が確認できました。
この結果から、メモリ設定はLambdaの実行環境の初期化だけでなく、リクエストを処理するアプリケーションコードの実行速度にも影響することが分かりました。
AWS Lambdaでは、メモリ設定に応じて割り当てられるCPUリソースも増加します。
そのため、今回の測定結果は、CPUリソースの割り当て量が処理時間に影響しているのではないかという仮説を裏付けるものと考えられます。
5.3 DynamoDB初期化時間の比較
| メモリ設定 | DynamoDB初期化 | Client生成 |
|---|---|---|
| 128MB | 2,229.6ms | 1,580.3ms |
| 256MB | 1,099.2ms | 759.7ms |
| 512MB | 525.5ms | 379.1ms |
今回の調査で、特に注目した部分です。
128MBでは約2.23秒かかっていたDynamoDBの初期化処理が、512MBでは約0.53秒まで短縮されました。
特にClient生成処理は、1,580.3msから379.1msまで短縮されました。
また、Resource ModelやService Modelの読み込み時間についても、同様の傾向が確認できました。
これらの結果から、Boto3の初期化処理はCPUリソースの割り当て量に大きく影響を受けている可能性が高いと考えられます。
一方、LambdaのInit Durationは、いずれのメモリ設定でも約0.76～0.80秒となっており、大きな差は見られませんでした。
つまり、今回の検証で確認できた主な性能改善は、LambdaのInit処理ではなく、Handler内部で実行されるBoto3の初期化処理やAPI処理において発生していたことが分かりました
6. 結果と考察
今回の調査を通じて、以下の4点を確認することができました。
- コールドスタート時に発生した遅延の大部分は、Handler内部のDynamoDB初期化処理で発生していることが分かりました。
- 初期化処理を細分化して計測した結果、特にBoto3のDynamoDB Client生成処理に最も多くの時間がかかっていることが確認できました。
- Lambdaのメモリ設定を128MBから512MBに増やしたところ、Handlerの実行時間が約76％短縮されました。
- 実際のメモリ使用量は約88～89MBで、ほぼ一定でした。そのため、メモリ容量の不足というよりも、メモリ設定に応じて割り当てられるCPUリソースが、処理時間に大きく影響していた可能性があると考えられます。
ブラウザの開発者ツールでAPIの応答時間を確認したところ、128MB設定では約4.18秒、512MB設定では約1.78秒でした。
7. 今後の改善案
今回の調査は、ボトルネックの特定とメモリ設定による性能比較までで、一旦区切りとしてもよいと考えています。
しかし、ユーザーが実際に感じる待ち時間をさらに短縮できないかと考え、次の改善案としてキャッシュの活用を検討しています。
EC2のような常時稼働するサーバーを利用していれば、Redisなどを使ったキャッシュの導入も考えられますが、今回のシステムはサーバーレス構成のため、S3を利用したキャッシュ方式を検討しています。
具体的には、DynamoDBに保存されているカレンダーデータをS3にもJSON形式で保存しておきます。
ユーザーがログインしてメイン画面にアクセスした際には、まずS3に保存されたカレンダーデータを取得して画面に表示します。
それと同時に、従来のGET /calendar APIも呼び出し、最新データを取得でき次第、画面の内容を更新する仕組みです。
今回のシステムでは、ユーザーに表示されるデータの更新頻度は高くありません。
そのため、まずキャッシュされたデータを表示し、バックグラウンドで最新データに更新することで、初回表示時の待ち時間を短縮できるのではないかと考えています。
また、S3に保存するデータのアクセス制御や、DynamoDBの更新内容をキャッシュへ反映する方法についても検討が必要です。
今後は、この構成を次の改善目標として、実際に実装・検証していきたいと考えています。
8. まとめ
当初、AWS Lambdaのコールドスタートという概念は知っていたものの、処理時間のうちどこまでがその影響によるものなのかは、正確に理解できていませんでした。
そこで、コールドスタートの仕組みを踏まえて処理ごとにログを細分化したところ、どの処理に時間がかかっているのかを把握できるようになりました。その中で、JavaでJDBCを用いてデータベース接続を準備するのと同様に、Boto3でもDynamoDBとの通信に必要な初期化処理が発生していることが分かりました。
ログで傾向を確認した後も、原因をより正確に特定するため、検証を複数回重ねました。あわせて、Lambdaのメモリ設定を変えながら測定を行い、設定ごとの性能差を数値で比較しました。
その結果、今回のケースでは、コード自体を変更するよりも、メモリ設定を引き上げてCPUリソースを確保する方法が、比較的容易かつ効果的な改善策であると判断しました。
今回の経験を通じて、性能問題に取り組む際に重要なのは、すぐにコードを修正したりリソースを増やしたりすることではなく、計測によってボトルネックを特定し、仮説を立て、実際の結果に基づいて検証することだと学びました。
また、今回の調査を進めるにあたっては、社内の先輩方から多くの助言をいただきました。検証の進め方や問題への向き合い方について貴重な学びを得られたことに、心より感謝しております。
今後も今回の学びを活かし、業務に役立ててまいります。
最後までお読みいただき、ありがとうございました。
