Serverless DeepDive #08:return後の処理は実行されるのか
S3保存をawaitする処理と、保存を残して返すasync handlerを比べます。保存件数と再Invokeの時刻から、成功応答へ何を含めるかを考えます。
Series: Serverless DeepDive (13 articles)
- …
- 9Serverless DeepDive #08:return後の処理は実行されるのか This article
検証構成
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する場合を比べます。
| 条件 | 設定 |
|---|---|
| region | ap-northeast-1 |
| managed runtime | nodejs26.x、Amazon Linux 2023 |
| 実際のNode.js version | v26.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の対象外なので、検証用に使います。

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 | 応答後の保存件数 |
|---|---|---|---|
| 1 | 2,495 ms | 2,499.68 ms | 1 |
| 2 | 1,569 ms | 1,572.11 ms | 1 |
| 3 | 1,567 ms | 1,568.81 ms | 1 |

画面の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の件数 |
|---|---|---|---|---|
| 1 | 13.026秒後 | 0 | 13.996秒後 | 0 |
| 2 | 12.710秒後 | 0 | 13.877秒後 | 0 |
| 3 | 12.896秒後 | 0 | 14.717秒後 | 0 |
次に、同じdetach関数へobserveを送りました。observeは新しい保存をせず、2秒待って記録を返します。6回とも、未awaitでreturnした呼び出しと同じ初期化UUIDが返りました。以前の保存結果もstoredになり、再び一覧を読むと各prefixに1件あります。
撮影用の追加1回を含む未awaitの7回を、awaiterの3回と比べます。REPORTのDurationと、PCで測った送信開始から応答完了までの時間は別の値です。
| 条件 | 回数 | REPORTのDuration | PCの送信開始から応答完了まで |
|---|---|---|---|
| 保存をawait | 3 | 1,568.81〜2,499.68 ms | 1,608.99〜2,790.03 ms |
| 未awaitでreturn | 7 | 2.56〜5.54 ms | 40.23〜353.33 ms |
保存をawaitすると、保存の待ち時間を応答へ含められます。PCの値には通信などの時間も入ります。短いREPORTは、後から動いた保存の時間や成功を示す値ではありません。
2組目のtrueでは、元のhandlerがreturnした時刻は1791686697383でした。再Invokeの送信は1791686714719です。以前の保存処理は1791686714739に再開し、PutObjectは1791686714831までに成功しました。数値はUnix epochのmillisecondです。

再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に撮影しました。

PCの応答完了から次のobserve送信まで、前の3組は17.318〜20.253秒空きました。追加のr4は407.130秒、約6分47秒です。これはPCの生出力にある時刻から計算した条件です。画像にこのPC時刻は表示されていません。前の3組と違い、r4では別の初期化UUIDが返りました。
| 記録 | UUIDの先頭8桁 | handlerの回数 | r4の保存件数 |
|---|---|---|---|
| 未awaitでreturn | 50864806 | 7 | 0 |
| 時間を空けてobserve | 4eebaeeb | 1 | 0 |

新しい環境で返った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に撮影しました。

保存処理が再び動いた理由と、成功が記録されなかった理由は特定できません。この待ち時間を実行環境の寿命とも決められません。今回確かめたのは、保存処理の開始後も、保存成功を確認できない条件があったことです。
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を残してreturn | 3 | FunctionErrorなし、recordを返した |
| 解決しないPromiseをawait | 1 | FunctionError=Unhandled、Runtime.ExitError |
| 直後にobserve | 1 | FunctionErrorなし、recordを返した |
awaitした呼び出しのDurationは30.94 msです。REPORTもStatus: error、Error Type: Runtime.ExitErrorでした。入力は届きましたが、return-resultのlogはなく、応答にerrorが入っています。

この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)
- …
- 9Serverless DeepDive #08:return後の処理は実行されるのか This article
Enjoyed reading this content? Let the author know!
Your likes, comments, shares, and saves help creators reach more builders.
Loading recommendations
Loading article