aws-lambda-powertools を試してみる（Tracer＆X-Ray 編その２）

概要

記事一覧はこちらです。

aws-lambda-powertools を試してみる（Tracer＆X-Ray 編その１） の続きです。

参照したサイト・書籍

1. SQS Tracing with AWSTraceHeader
   https://github.com/aws/aws-xray-sdk-node/issues/208

   • SQS や SNS で X-Ray はサポートされたが Service Map でつなげて表示するところまではまだ実現できていないとのこと。

目次

1. API Gateway の Endpoint にメッセージを送信して X-Ray の表示内容を確認する
2. SQS は X-Ray の円がつながらず SNS はつながる理由とは？
3. logger.structure_logs(...)で AWSTraceHeader と trace_id を出力するよう設定して API Gateway → Lambda → SQS → Lambda の流れを CloudWatch Logs Insights で追えるようにする
4. boto3 のインスタンスの生成はグローバルで実施した方が２回目以降は速い
5. 最後に

手順

API Gateway の Endpoint にメッセージを送信して X-Ray の表示内容を確認する

Postman からメッセージを送信すると 200 OK が返ってきました。

AWS マネジメントコンソールの X-Ray の Service Map を見ると以下の画面が表示されました。

• 赤丸：API Gateway → Lambda（recvMsg）
• 青色：Lambda（recvMsg） → DynamoDB → DynamoDB Streams → Lambda（processSampleTableStream）
• 緑色：Lambda（recvMsg） → SQS → Lambda（processSampleQueue）
• 黄色：Lambda（recvMsg） → SNS → Lambda（processSampleTopic）
• 紫色：Lambda（recvMsg） → Lambda（processSync）
• オレンジ色：Lambda（recvMsg） → Lambda（processAsync）

気になったのは、

• DynamoDB は X-Ray がまだサポートしていないので円がつながらないのは分かるのですが、SQS は AWS X-Ray が Amazon SQS をサポート の記事が出ているにもかかわらずこちらもつながって表示されません。
• SNS も Amazon SNS で AWS X-Ray のサポートを追加 の記事が出ていますが、こちらはつながって表示されています。
• Lambda の呼び出しは同期呼び出しだと円が２つ、非同期呼び出しだと１つです。

Traces には以下の一覧が表示されており、

メソッドに POST と表示されている行の詳細を表示すると以下のデータが表示されました。

• Cold Start 時は Initialization の時間がかかります。
• 大した処理を記述していない Lambda でも同期呼び出しだと初回は Initialization 並みの時間がかかっています。まあ当然ですね。
• @tracer.capture_method を付与した関数名が表示されており、関数毎の処理時間が分かります。

SQS は X-Ray の円がつながらず SNS はつながる理由とは？

Lambda（recvMsg）の CloudWatch のログを見ると decorate のログの message.headers.X-Amzn-Trace-Id に X-Ray のトレースID が出力されています。

Lambda（recvMsg）の logger.debug(event) が出力したログを見ると、AWSTraceHeader（message.headers.X-Amzn-Trace-Id の値が出力されています）と traceId に同じ値がセットされています。

Lambda（processSampleQueue）の CloudWatch の decorate のログを見ると message.Records[0].attributes.AWSTraceHeader に message.headers.X-Amzn-Trace-Id に出力されていたトレースID が含まれています（メッセージ送信時にセットしていないにもかかわらず）。

Lambda（processSampleQueue）の logger.debug(event) が出力したログを見ると、traceId には AWSTraceHeader にセットされていたものとは別のトレースID がセットされています。

Lambda（processSampleTopic）の CloudWatch の decorate のログを見ると message.headers.X-Amzn-Trace-Id に出力されていたトレースID はどこにもセットされていませんが、

Lambda（processSampleTopic）の logger.debug(event) が出力したログを見ると、traceId に message.headers.X-Amzn-Trace-Id に出力されていたトレースID がセットされています。

ということで、SQS 経由だとトレースID が引き継がれませんが SNS 経由だと引き継がれるからという理由のようです。SQS は X-Ray でサポートされていると発表されているので円がつながるようにできそうな気がしたのですが、今回調べた限りではその方法はさっぱり分かりませんでした。。。

logger.structure_logs(...)で AWSTraceHeader と trace_id を出力するよう設定して API Gateway → Lambda → SQS → Lambda の流れを CloudWatch Logs Insights で追えるようにする

SQS 経由の場合、メッセージの送信元の Lambda と受信先の Lambda でトレースID は異なりますが AWSTraceHeader で送信元のトレースID は伝わるようなので、logger.structure_logs(...) で AWSTraceHeader を出力するようにしておけば一連の流れをログで追えそうかなと思いました。ついでにトレースID も出力します。

API Gateway から呼び出される Lambda（recvMsg）では以下のように実装し、

    awsTraceHeader = event['headers']['X-Amzn-Trace-Id']
    logger.structure_logs(append=True,
                          AWSTraceHeader=awsTraceHeader,
                          traceId=xray_recorder.current_segment().trace_id)

SQS 経由で呼び出される Lambda（processSampleQueue）では以下のように実装します。AWSTraceHeader はメッセージの属性に付加されるので、最初は None にしておいてメッセージの処理をする時に record['attributes']['AWSTraceHeader'] で上書きします。

    logger.structure_logs(append=True,
                          AWSTraceHeader=None,
                          traceId=xray_recorder.current_segment().trace_id)
    ..........

    for record in event['Records']:
        logger.structure_logs(append=True,
                              AWSTraceHeader=record['attributes']['AWSTraceHeader'])
        ..........

AWS マネジメントコンソールで CloudWatch Logs のロググループを表示してから、Lambda（recvMsg）と Lambda（processSampleQueue）のログを選択して CloudWatch Logs Insight で表示します。

クエリを以下の内容に変更してから実行すると、

fields @timestamp, level, substr(AWSTraceHeader, 0, 40), function_name, message
| filter AWSTraceHeader =~ /1-5f008baf-76bb78b8aaa6a3e0546581c8/
| sort @timestamp desc
| limit 20

• AWSTraceHeader だけ指定した場合 Lambda（processSampleQueue）で出力される文字列は Parent 等項目が追加されて少し長くなるので、確認したい文字列だけ出力されるよう substr(AWSTraceHeader, 0, 40) で指定します。
• Lambda（recvMsg）のログなのか Lambda（processSampleQueue）のログなのかが分かるよう function_name を出力します。
• 今回は処理内容がシンプルに分かればよいので @message → message に変更します。
• API Gateway で発行されたトレースID 1-5f008baf-76bb78b8aaa6a3e0546581c8 が含まれているログを取得したいので filter AWSTraceHeader =~ /1-5f008baf-76bb78b8aaa6a3e0546581c8/ を追加します。

API Gateway → Lambda（recvMsg） → SQS → Lambda（processSampleQueue）の流れをログで追うことができました。SQS にメッセージを送信する時に orderedItem を１件ずつ分けずに event['body'] まるごと送信している失敗にも気づいてしまいましたが。。。

また SQS にはメッセージを２回しか送信していないのに Lambda（processSampleQueue）のログがなぜ３回出ているの？と思ったのですが、decorate のログは１回目は以下の内容なのですが、

２回目は @logger.inject_lambda_context と logger.structure_logs(...) で追加された項目が出ていたためでした。

boto3 のインスタンスの生成はグローバルで実施した方が２回目以降は速い

sample_service/apigw_handler.py で boto3 のインスタンスを生成するタイミングをハンドラーの前にしていますが、

..........

dynamodb_sample_table_tbl = boto3.resource('dynamodb').Table('sample-table')
sqs_client = boto3.client('sqs')
sns_client = boto3.client('sns')
lambda_client = boto3.client('lambda')


# @logger.inject_lambda_context を付けておくとログ出力時に context にセットされている
# function_name 等の情報がセットされる
# Capturing context Lambda info
# https://awslabs.github.io/aws-lambda-powertools-python/core/logger/#capturing-context-lambda-info
@logger.inject_lambda_context
@tracer.capture_lambda_handler
def recv_msg(event, context):
    ..........

この方式で API Gateway にアクセスすると Lambda（recvMsg）の実行時間は cold start がなければ 321ms、278ms、252ms でした。

これをハンドラーが呼び出されてから都度生成されるように以下のように変更してみたところ、

@tracer.capture_method
def put_item_to_dynamodb(orderNumber, orderedItem):
    dynamodb_sample_table_tbl = boto3.resource('dynamodb').Table('sample-table')
    dynamodb_sample_table_tbl.put_item(
        Item={
            ..........

Lambda（recvMsg）の実行時間は cold start がなければ 627ms、515ms、554ms でした。約２倍です。

以前ユニットテストを書いた時にはエラーが出るのでハンドラー関数内で生成するようにしましたが、グローバルで１度だけ生成するようにした方がやっぱり速いんですね。当然といえば当然。。。　ユニットテストでエラーが出るのを解決する別の方法を調べることにします。

最後に

• Logger は JSON で出力できたり、context の function_name 等の情報を自動でセットしてくれたりするのが便利です。
• logger.structure_logs(...) で共通で出力しておきたい項目をセットしておけるのも使い勝手がいいなと思いました。
• 始めて X-Ray を使ったのですが、Serverless Framework の設定と Tracer で本当に簡単に連携できるようになるので驚きでした。X-Ray はなんか面倒な印象があったのですが、こんなに簡単に使えるならば積極的に使っていきたいと思います。

AWS Black Belt Online Seminar AWS X-Ray 資料及び QA 公開 も見つけたので、後で見ておきましょう。

履歴

2020/07/05
初版発行。