YMLib - other - SQS+Lambda② ログ調査

SQS+Lambda② ログ調査

2024/12/31

Lambdaのログを確認します。

SQS+Lambdaで作ったものに10秒スリープを入れます。

1:
2:
3:
4:
5:
6:
7:
8:
9:
10:
11:

import json
import time

def lambda_handler(event, context):
    # TODO implement
    time.sleep(10)
    print(event)
    return {
        'statusCode': 200,
        'body': json.dumps('Hello from Lambda!')
    }

SQSを開き「メッセージを送受信」をクリックしメッセージを送受信画面でメッセージを入力し「メッセージを送信」をクリックします。

CloudWatchにログが出力されていますがループしているようです。

INIT_START Runtime Version: python:3.9.v64 Runtime Version ARN: arn

:aws:lambda:ap-northeast-1::runtime:57efdf
START RequestId: f256 Version: $LATEST
2024-12-31T09:15:43.938Z f256 Task timed out after 3.01 seconds
END RequestId: f256
REPORT RequestId: f256 Duration: 3005.61 ms Billed Duration: 300

0 ms Memory Size: 128 MB Max Memory Used: 30 MB Init Durat

ion: 75.09 ms

INIT_START Runtime Version: python:3.9.v64 Runtime Version ARN: arn

:aws:lambda:ap-northeast-1::runtime:57efdf
START RequestId: 8d25 Version: $LATEST
2024-12-31T09:16:13.792Z 8d25 Task timed out after 3.01 seconds
END RequestId: 8d25
REPORT RequestId: 8d25 Duration: 3005.08 ms Billed Duration: 300

0 ms Memory Size: 128 MB Max Memory Used: 8 MB

INIT_START Runtime Version: python:3.9.v64 Runtime Version ARN: arn

:aws:lambda:ap-northeast-1::runtime:57efdf
START RequestId: 040d Version: $LATEST
2024-12-31T09:16:43.798Z 040d Task timed out after 3.01 seconds
END RequestId: 040d
REPORT RequestId: 040d Duration: 3005.78 ms Billed Duration: 300

0 ms Memory Size: 128 MB Max Memory Used: 8 MB

1行目。Runtimeは同じもののようです。

INIT_START Runtime Version: python:3.9.v64 Runtime Version ARN: arn

:aws:lambda:ap-northeast-1::runtime:57efdf

2行目。RequestIdは毎回違うものになる模様です。

START RequestId: f256 Version: $LATEST

3行目。Task timed outと表示されています。

2024-12-31T09:15:43.938Z f256 Task timed out after 3.01 seconds

4行目。処理が終わったようです。

END RequestId: f256

5行目。INIT_STARTの行からREPORTの行までが１回の処理のログのようです。最初のかたまりのREPORTの行だけDurationの表示があります。

REPORT RequestId: f256 Duration: 3005.61 ms Billed Duration: 300

0 ms Memory Size: 128 MB Max Memory Used: 30 MB Init Durat

ion: 75.09 ms

それぞれの項目の値について考察。

Duration	3005.61 ms	全体の処理時間？
Billed Duration	3000 ms	課金対象時間？
Memory Size	128 MB
Max Memory Used	30 MB	利用したメモリ？
Init Duration	75.09 ms	初期化にかかった時間？

ログのかたまりごとの値は以下の通りでした。

RequestId	f256	8d25	040d
Task timed out	09:15:43.938	09:16:13.792	09:16:43.798
Duration	3005.61 ms	3005.08 ms	3005.78 ms
Billed Duration	3000 ms	3000 ms	3000 ms
Memory Size	128 MB	128 MB	128 MB
Max Memory Used	30 MB	8 MB	8 MB
Init Duration	75.09 ms	-	-

原因調査

Lambdaのタイムアウト時間が3秒になっていたため、10秒sleep中にLambdaがタイムアウトしていたようです。

SQSの可視性タイムアウトが30秒になっていたため、Lambdaの処理がタイムアウトした後、メッセージは残ったままになり30秒経過後メッセージが再度見えるようになりLambdaが起動するといった流れを繰り返しているようです。

Lambdaのタイムアウトを延長

Lambdaのタイムアウトを20秒に延長します。

Lambdaの[設定]を選択します。一般設定の欄にタイムアウトが「 0 分 3 秒」と表示されています。同じ欄にある「編集」をクリックします。

タイムアウト欄を20秒に変更し画面のしたの「保存」を押します。

CloudWatchを確認します。

10秒後処理が終わったようです。

複数メッセージの処理

10秒以内にメッセージを３つ送信しCloudWatchを確認します。

順番に処理が行われたようです。

▲ PageTop ■ Home