AWS Builder Center

Serverless DeepDive #08:return後の処理は実行されるのか

S3保存をawaitする処理と、保存を残して返すasync handlerを比べます。保存件数と再Invokeの時刻から、成功応答へ何を含めるかを考えます。

Series: Serverless DeepDive (13 articles)

  1. …
  2. 9
    Serverless DeepDive #08:return後の処理は実行されるのか This article
Senior Evangelist

検証構成

3組の比較で、未完了のS3保存を残してreturnした6回は、成功応答を返しました。それでも、約13〜15秒後のS3には対象のobjectがありませんでした。同じ初期化UUIDが返った再Invokeでは、元の保存が完了しています。追加の1回(r4)では、次のInvokeより前に保存処理の開始logが出ましたが、保存成功を確認できませんでした。
#07では、関数・version・aliasを選び、呼び出し先で読める状態を比べました。今回は、実行環境に残す保存処理の完了を追います。
応答を早く返せても、保存が終わったことにはなりません。今回は、保存をawaitする処理と、Promiseを残して返す処理を比べます。Promiseは、非同期処理の結果を後で受け取るためのobjectです。InvokeはLambda関数を呼ぶAPIです。
Invokeごとの短い処理で、実行環境の準備や終了をAWSへ任せたい場合はLambdaが候補です。保存の完了を成功応答へ含める順序は、handlerで決めます。
同じhandlerの4関数を作りました。awaiterは保存をawaitします。detachtrueとdetachfalseは待たずに返します。promiseでは、解決しないPromiseを残して返す場合と、awaitする場合を比べます。
条件設定
regionap-northeast-1
managed runtimenodejs26.x、Amazon Linux 2023
実際のNode.js versionv26.8.2
memory / architecture各512 MB / arm64
timeout / reserved concurrency各5秒 / 各1
実行方式通常on-demand、同期Invoke、合計22回
保存先同じS3 bucket、run_idごとに別のkey
保存処理1,500 ms待ってからPutObject、自動retryなし
2026年10月11日の公式runtime一覧 から、最新のNode.jsを選びました。Node.js 26はpublic Previewです。SLAとTechnical Supportの対象外なので、検証用に使います。
共通labのAWS SDK runnerから4つのLambdaへ同期Invokeし、待機・S3一覧・再Invokeの順に保存を比較し、CloudWatch Logsを読む検証時の構成
S3への実線はawaiterと二つのdetach関数の保存です。promiseはS3へ保存しません。点線は、PCのAWS SDK runnerがS3の一覧・objectとCloudWatch Logsを読む経路です。reserved concurrency は、関数専用の同時実行枠を確保し、その上限も定めます。今回の値1でも、r4では初期化UUIDが変わりました。

保存処理を作る

検証では、保存処理の前に1,500 ms待ちます。returnの前後を分けて観測するための待ち時間です。S3の応答速度を比較するbenchmarkには使いません。
次は、実行したhandlerの全体です。handlerの外のUUIDで、同じmodule初期化から続いた呼び出しかを確認します。保存には元のRequestIdとrun_idを残します。PutObjectの成功後に、stored_msをlogへ出します。
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
const { randomUUID } = require("node:crypto");
const { setTimeout: sleep } = require("node:timers/promises");

const environmentId = randomUUID();
const records = [];
const orphanPromises = [];
let activeRequestId = null;
let activeMode = null;
let calls = 0;
let client;
const modes = ["await-store", "detach-store", "observe", "orphan-promise", "await-promise"];

function identifier(value, field) {
if (typeof value !== "string" || !/^[a-z0-9-]{1,64}$/.test(value))
throw new TypeError(`${field} must match [a-z0-9-]{1,64}`);
return value;
}

function delay(value) {
if (!Number.isInteger(value) || value < 0 || value > 3000)
throw new TypeError("delay_ms must be between 0 and 3000");
return value;
}

function snapshot() {
return records.map(
({ id, request_id, status, put_started_ms, stored_ms, active_request_id }) => ({
id,
request_id,
status,
put_started_ms: put_started_ms ?? null,
stored_ms: stored_ms ?? null,
active_request_id: active_request_id ?? null,
}),
);
}

async function store(record, delayMs) {
await sleep(delayMs);
record.put_started_ms = Date.now();
record.active_request_id = activeRequestId;
record.active_mode = activeMode;
record.status = "put-started";
console.log(JSON.stringify({ phase: "return-put-started", ...record }));
const bucket = process.env.LAB_EVIDENCE_BUCKET;
const prefix = process.env.LAB_EVIDENCE_PREFIX;
if (!bucket || !prefix) throw new Error("storage is not configured");
const { S3Client, PutObjectCommand } = require("@aws-sdk/client-s3");
if (!client) client = new S3Client({ maxAttempts: 1 });
record.sdk = require("@aws-sdk/client-s3/package.json").version;
record.key = `${prefix}${record.run_id}/${record.id}.json`;
await client.send(
new PutObjectCommand({ Bucket: bucket, Key: record.key, Body: JSON.stringify(record) }),
);
record.stored_ms = Date.now();
record.status = "stored";
console.log(JSON.stringify({ phase: "return-store-success", ...record }));
}

console.log(
JSON.stringify({ phase: "return-init", environment_id: environmentId, node: process.version }),
);

exports.handler = async (event, context) => {
if (!event || typeof event !== "object" || Array.isArray(event))
throw new TypeError("event must be a JSON object");
const mode = event.mode ?? "observe";
if (!modes.includes(mode)) throw new TypeError("unknown mode");
const id = identifier(event.id, "id");
const runId = identifier(event.run_id, "run_id");
const delayMs = delay(event.delay_ms ?? 1500);
if (event.wait_for_event_loop !== undefined && typeof event.wait_for_event_loop !== "boolean")
throw new TypeError("wait_for_event_loop must be boolean");
const propertyPresent = "callbackWaitsForEmptyEventLoop" in context;
const propertyBefore = context.callbackWaitsForEmptyEventLoop ?? null;
if (event.wait_for_event_loop !== undefined)
context.callbackWaitsForEmptyEventLoop = event.wait_for_event_loop;
calls += 1;
activeRequestId = context.awsRequestId;
activeMode = mode;
const record = {
id,
run_id: runId,
mode,
request_id: context.awsRequestId,
environment_id: environmentId,
node: process.version,
count: calls,
started_ms: Date.now(),
delay_ms: delayMs,
callback_property_present: propertyPresent,
callback_property_before: propertyBefore,
callback_property_after: context.callbackWaitsForEmptyEventLoop ?? null,
pending_before: snapshot(),
orphan_promises: orphanPromises.length,
};
console.log(JSON.stringify({ phase: "return-enter", ...record }));
if (mode === "await-store" || mode === "detach-store") {
if (records.length >= 64) throw new Error("record limit reached");
const workRecord = { ...record, status: "scheduled" };
records.push(workRecord);
const work = store(workRecord, delayMs);
if (mode === "await-store") await work;
else
void work.catch((error) => {
workRecord.status = "failed";
console.error(
JSON.stringify({ phase: "return-store-error", id, run_id: runId, error: error.name }),
);
});
} else if (mode === "observe") {
await sleep(delayMs);
} else {
if (orphanPromises.length >= 64) throw new Error("promise limit reached");
const never = new Promise(() => {});
orphanPromises.push(never);
if (mode === "await-promise") await never;
}
record.pending_after = snapshot();
record.finished_ms = Date.now();
record.orphan_promises = orphanPromises.length;
console.log(JSON.stringify({ phase: "return-result", ...record }));
return record;
};
S3に入るJSONは、PutObjectを送る前の記録です。そのstatusはput-startedです。保存成功を示すstoredとstored_msは、成功後のlogとhandlerの応答へ残します。S3のobjectの存在と、成功logの元RequestIdを照合しました。
active_request_idは、最後にhandlerへ入った時点の値です。再Invokeの送信時刻は、PC側で別に測ります。新しいhandlerへ入る前に以前のtimerが動く場合もあるため、この変数だけで実行中のInvokeを決めません。

awaitして返す

awaiterへ3回送りました。3回とも、PutObjectの成功を待ってからreturnしています。各応答のpending_afterには、保存結果がstoredとして入りました。応答後にS3を一覧で読むと、各run_idに1件ずつあります。
組handlerの開始からreturnまでLambdaのDuration応答後の保存件数
12,495 ms2,499.68 ms1
21,569 ms1,572.11 ms1
31,567 ms1,568.81 ms1
S3保存をawaitした3回で、元RequestIdとPutObject成功時刻を確認したCloudWatchの実測画面
画面のput_msとstored_msはUTC日時です。reqはRequestIdの先頭8桁を表示しています。以降のCloudWatch画像も同じ表示形式です。
初回はSDKの読み込みとclientの作成も含みます。3回の差をS3だけの処理時間にはしません。今回は、追加した待ち時間と保存の完了を、応答の前へ含められたことを確認しました。
S3の整合性モデル では、成功したPUTの後に始めたGETとLISTで、その保存結果を読めます。保存先とrun_idを揃えて確認しました。

未完了処理を残す

二つのdetach関数では、同じ保存処理を始めた後、そのPromiseをawaitせずに返しました。callbackWaitsForEmptyEventLoopへ、それぞれtrueとfalseを代入します。
6回とも、応答時の保存はscheduledです。put_started_msとstored_msはnullでした。PCで3秒以上待ち、他の関数の測定と証拠の収集を進めてから、各prefixを一覧で読みました。
組trueの応答から一覧までの経過trueの件数falseの応答から一覧までの経過falseの件数
113.026秒後013.996秒後0
212.710秒後013.877秒後0
312.896秒後014.717秒後0
次に、同じdetach関数へobserveを送りました。observeは新しい保存をせず、2秒待って記録を返します。6回とも、未awaitでreturnした呼び出しと同じ初期化UUIDが返りました。以前の保存結果もstoredになり、再び一覧を読むと各prefixに1件あります。
撮影用の追加1回を含む未awaitの7回を、awaiterの3回と比べます。REPORTのDurationと、PCで測った送信開始から応答完了までの時間は別の値です。
条件回数REPORTのDurationPCの送信開始から応答完了まで
保存をawait31,568.81〜2,499.68 ms1,608.99〜2,790.03 ms
未awaitでreturn72.56〜5.54 ms40.23〜353.33 ms
保存をawaitすると、保存の待ち時間を応答へ含められます。PCの値には通信などの時間も入ります。短いREPORTは、後から動いた保存の時間や成功を示す値ではありません。
2組目のtrueでは、元のhandlerがreturnした時刻は1791686697383でした。再Invokeの送信は1791686714719です。以前の保存処理は1791686714739に再開し、PutObjectは1791686714831までに成功しました。数値はUnix epochのmillisecondです。
未awaitのtrueとfalseで、元のreturnより後にS3保存が完了したCloudWatchの実測画面
再Invokeと以前の保存処理の再開は、ほぼ同時に見えます。PCとLambdaの時計は別で、時計差は測っていません。数十msの差は目安です。Lambda側では、6組ともobserveのSTARTと保存処理開始logの差が0〜1 msでした。実行環境の再利用 では、未完了のbackground processやcallbackが再開し得ると説明されています。今回も、その説明と対応する動きを観測できました。実際の凍結時刻や内部の配置は、この記録から特定できません。

時間を空けてInvokeする

撮影用に、trueの未await保存をもう1回送りました。入力のrun_idはr4-trueです。正常応答の後、同じS3 prefixにobjectがないことを確認しました。
次の画像は、observe送信(02:53:46 UTC)の約18秒前、02:53:28 UTCに撮影しました。
追加r4の未await保存で、再Invoke前の同じS3 prefixがObjects0だった実Console画面
PCの応答完了から次のobserve送信まで、前の3組は17.318〜20.253秒空きました。追加のr4は407.130秒、約6分47秒です。これはPCの生出力にある時刻から計算した条件です。画像にこのPC時刻は表示されていません。前の3組と違い、r4では別の初期化UUIDが返りました。
記録UUIDの先頭8桁handlerの回数r4の保存件数
未awaitでreturn5086480670
時間を空けてobserve4eebaeeb10
時間を空けたr4の再Invokeで、初期化UUIDと回数が変わったCloudWatchの実測画面
新しい環境で返ったobserveのpending_beforeとpending_afterは空です。元の環境のlogには、保存処理開始を示すreturn-put-startedが1件ありました。02:53:01.030 UTCで、元handlerのreturnから361.192秒後、observeの送信開始から45.956秒前です。約6分1秒後、約46秒前にあたります。
このlogはtimerの待機後、SDKのclient.sendへ進む前に出す記録です。同じstreamにその後の成功・errorのlogはなく、S3の一覧も0件でした。保存処理が動いたことと、保存が完了したことを分けて読みます。
再Invokeの後にも、同じS3 prefixを読み直しました。次の画像は、observe送信の約54秒後、02:54:40 UTCに撮影しました。
追加r4で別UUIDへ再Invokeした後も、同じS3 prefixがObjects0のままだった実Console画面
保存処理が再び動いた理由と、成功が記録されなかった理由は特定できません。この待ち時間を実行環境の寿命とも決められません。今回確かめたのは、保存処理の開始後も、保存成功を確認できない条件があったことです。

contextの設定を比べる

event loopは、timerやI/Oの処理を進める仕組みです。callback方式では、これが空になるまで応答を待つかをcallbackWaitsForEmptyEventLoopで指定します。
今回のtrueとfalseでは、保存の完了に差は出ませんでした。Node.js 26のcontextには、代入前のcallbackWaitsForEmptyEventLoopが存在していません。同じcontext objectへこのプロパティを追加し、trueまたはfalseを代入しました。それでも、保存を待つ動きは変わりませんでした。
Node.js handlerの仕様 では、callback-based handlerはNode.js 22までの対応です。このプロパティの説明も、callback方式の節にあります。Node.js 24以降のasync handlerへ、その完了条件を持ち込まないようにします。

Promiseを比較する

解決しないPromiseを作り、handlerの返す値とは結び付けずに残しました。3回とも正常にrecordが返り、Durationは4.69、4.25、3.67 msです。保留Promiseがあるだけで、今回のasync handlerの終了を待つ動きにはなりませんでした。
次に、同じ形の解決しないPromiseを新しく作ってawaitしました。ここでは5秒のtimeoutまで待つと予想しましたが、結果は違いました。
条件回数結果
解決しないPromiseを残してreturn3FunctionErrorなし、recordを返した
解決しないPromiseをawait1FunctionError=Unhandled、Runtime.ExitError
直後にobserve1FunctionErrorなし、recordを返した
awaitした呼び出しのDurationは30.94 msです。REPORTもStatus: error、Error Type: Runtime.ExitErrorでした。入力は届きましたが、return-resultのlogはなく、応答にerrorが入っています。
保留Promiseを残した3回の正常応答と、awaitした1回のRuntime.ExitErrorを確認した実測画面
このPromiseにはtimerやI/Oを付けていません。進める処理がない保留Promiseをawaitすると、timeoutを待たずにruntimeが終了しました。原因は特定していません。全ての保留Promiseが同じ時間で失敗するとは決めません。timerで待つS3保存の対照では、awaitした処理を完了できています。

測定を試す

共通labのreturn-work.jsonを使いました。handlerはhandlers/return-work/index.cjsです。scenarioをvalidateし、CDKで新しい4関数、log group、実行role、S3 bucketを作りました。測定時の関数設定とconcurrencyを取得しました。AWSから取得したstackのtemplateでも、4roleのS3 policyが検証用bucketのprefixへ限られる設定を照合しました。
同じhandlerを手元で試す場合は、上のcodeをindex.jsとしてzipへ入れます。handler名はindex.handlerです。runtime同梱のSDKを使います。S3 bucket名をLAB_EVIDENCE_BUCKETへ設定します。LAB_EVIDENCE_PREFIXはevidence/dd08/のように、末尾を「/」にします。実測ではevidence/dd08-20261011/を使いました。
1
zip function.zip index.js
必要なS3権限は、対象prefixへのs3:PutObjectです。PC側で一覧とJSONを確認する場合は、s3:ListBucketとs3:GetObjectも必要です。logを出せる実行roleを使い、runtime、memory、timeout、architecture、reserved concurrency 1を条件表へ揃えます。
4関数を同じ構成で試すには、account quotaの未予約枠から100を残し、合計4を予約できる余地が必要です。reserved concurrency 1を設定できないaccountでは、同じ再現条件になりません。
次は同期Invokeの例です。profile、関数名、run_idを自分の検証用に置き換えます。同じrun_idへ結果を混ぜず、関数の更新も測定中は避けます。
1
2
3
4
5
6
7
AWS_MAX_ATTEMPTS=1 aws lambda invoke \
--profile YOUR_PROFILE --region ap-northeast-1 \
--function-name YOUR_AWAITER \
--invocation-type RequestResponse \
--cli-binary-format raw-in-base64-out \
--payload '{"id":"await-store-1","run_id":"run-await-1","mode":"await-store","delay_ms":1500}' \
await-store-1.json

保存件数を確かめる

未awaitの対照では、modeをdetach-storeへ変え、wait_for_event_loopへtrueまたはfalseを渡します。別の関数でそれぞれ試しました。run_idをrun-detach-1、prefixをevidence/dd08/とした場合、次のcommandで対象の件数を読みます。今回のように対象が0件か1件の条件では、1pageのKeyCountで確認できます。
1
2
3
4
AWS_MAX_ATTEMPTS=1 aws s3api list-objects-v2 \
--profile YOUR_PROFILE --region ap-northeast-1 \
--bucket YOUR_BUCKET --prefix evidence/dd08/run-detach-1/ \
--no-paginate --query KeyCount --output text
送信の順は、未awaitのInvoke、PCで3秒以上待機、S3一覧、同じ関数へobserveの再Invoke、S3一覧です。実測の最初の3組では、間に他の測定と収集も行い、最初の一覧まで約13〜15秒かかりました。InvokeのStatusCodeだけで保存成功とせず、FunctionError、応答内のstatus、log、S3の件数を比べます。
再Invokeでは、mode: observeとdelay_ms: 2000を渡します。idとrun_idは観測用の別の値にします。以前のPromiseを直接awaitしているわけではなく、動いている時間を設けて観測する入力です。環境が再利用されることを指定するものではありません。

まとめ

return後に残した処理が動く場合はありました。最初の3組は再Invokeで保存が完了し、r4は保存処理の開始logが出ても、S3が0件のままでした。処理の開始と保存完了は分けて判断します。
実行環境の準備・凍結・再利用・終了は、Lambda側が扱います。今回の通常on-demandでは、凍結時期や次のInvoke先を指定する手段は確認していません。次も同じ環境が選ばれることは前提にできません。保存完了を成功応答の条件にするなら、利用者はhandlerが返すPromiseに保存のawaitを含めます。その待ち時間は応答にも入ります。
早い受付と後続処理を分けたい場合は、queueなどへの受け渡しと、後から確認できる完了記録を設計します。受け渡しの成功、配送・再試行・重複への対応と性能は、別に確かめる必要があります。これらは今回の実測には含めていません。

Series: Serverless DeepDive (13 articles)

  1. …
  2. 9
    Serverless DeepDive #08:return後の処理は実行されるのか This article
Any opinions in this article are those of the individual author and may not reflect the opinions of AWS.
Enjoyed reading this content? Let the author know!

Your likes, comments, shares, and saves help creators reach more builders.

Loading recommendations

Loading article