Reduce Node Lambda cold-start overhead with synchronous ESM loader hooks

integration_tests_local/snapshots/logs/cjs-proactive-init_node26.log

@@ -21,7 +21,7 @@ START RequestId: XXXX	Version: $LATEST
   "timestamp": "XXXX-XX-XXTXX:XX:XX.XXXZ",
   "level": "ERROR",
   "requestId": "XXXX",
-  "message": "(node:XX) TimeoutOverflowWarning: XXXX does not fit into a 32-bit signed integer.\nTimeout duration was set to 1."
+  "message": "[dd.trace_id=XXXX dd.span_id=XXXX] (node:XX) TimeoutOverflowWarning: XXXX does not fit into a 32-bit signed integer.\nTimeout duration was set to 1."
 }
 {
   "traces": [
@@ -133,7 +133,7 @@ START RequestId: XXXX	Version: $LATEST
   "timestamp": "XXXX-XX-XXTXX:XX:XX.XXXZ",
   "level": "ERROR",
   "requestId": "XXXX",
-  "message": "(node:XX) TimeoutOverflowWarning: XXXX does not fit into a 32-bit signed integer.\nTimeout duration was set to 1."
+  "message": "[dd.trace_id=XXXX dd.span_id=XXXX] (node:XX) TimeoutOverflowWarning: XXXX does not fit into a 32-bit signed integer.\nTimeout duration was set to 1."
 }
 {
   "traces": [
@@ -244,8 +244,10 @@ START RequestId: XXXX	Version: $LATEST
   "timestamp": "XXXX-XX-XXTXX:XX:XX.XXXZ",
   "level": "ERROR",
   "requestId": "XXXX",
-  "message": "(node:XX) TimeoutOverflowWarning: XXXX does not fit into a 32-bit signed integer.\nTimeout duration was set to 1."
+  "message": "[dd.trace_id=XXXX dd.span_id=XXXX] (node:XX) TimeoutOverflowWarning: XXXX does not fit into a 32-bit signed integer.\nTimeout duration was set to 1."
 }
+END RequestId: XXXX
+REPORT RequestId: XXXX	Duration: XXXX ms
 {
   "traces": [
     [
@@ -333,8 +335,6 @@ START RequestId: XXXX	Version: $LATEST
     ]
   ]
 }
-END RequestId: XXXX
-REPORT RequestId: XXXX	Duration: XXXX ms
 START RequestId: XXXX	Version: $LATEST
 {
   "e": XXXX,
@@ -355,7 +355,7 @@ START RequestId: XXXX	Version: $LATEST
   "timestamp": "XXXX-XX-XXTXX:XX:XX.XXXZ",
   "level": "ERROR",
   "requestId": "XXXX",
-  "message": "(node:XX) TimeoutOverflowWarning: XXXX does not fit into a 32-bit signed integer.\nTimeout duration was set to 1."
+  "message": "[dd.trace_id=XXXX dd.span_id=XXXX] (node:XX) TimeoutOverflowWarning: XXXX does not fit into a 32-bit signed integer.\nTimeout duration was set to 1."
 }
 {
   "traces": [
@@ -466,10 +466,8 @@ START RequestId: XXXX	Version: $LATEST
   "timestamp": "XXXX-XX-XXTXX:XX:XX.XXXZ",
   "level": "ERROR",
   "requestId": "XXXX",
-  "message": "(node:XX) TimeoutOverflowWarning: XXXX does not fit into a 32-bit signed integer.\nTimeout duration was set to 1."
+  "message": "[dd.trace_id=XXXX dd.span_id=XXXX] (node:XX) TimeoutOverflowWarning: XXXX does not fit into a 32-bit signed integer.\nTimeout duration was set to 1."
 }
-END RequestId: XXXX
-REPORT RequestId: XXXX	Duration: XXXX ms
 {
   "traces": [
     [
@@ -556,6 +554,8 @@ REPORT RequestId: XXXX	Duration: XXXX ms
     ]
   ]
 }
+END RequestId: XXXX
+REPORT RequestId: XXXX	Duration: XXXX ms
 START RequestId: XXXX	Version: $LATEST
 {
   "e": XXXX,
@@ -576,7 +576,7 @@ START RequestId: XXXX	Version: $LATEST
   "timestamp": "XXXX-XX-XXTXX:XX:XX.XXXZ",
   "level": "ERROR",
   "requestId": "XXXX",
-  "message": "(node:XX) TimeoutOverflowWarning: XXXX does not fit into a 32-bit signed integer.\nTimeout duration was set to 1."
+  "message": "[dd.trace_id=XXXX dd.span_id=XXXX] (node:XX) TimeoutOverflowWarning: XXXX does not fit into a 32-bit signed integer.\nTimeout duration was set to 1."
 }
 {
   "traces": [
@@ -686,7 +686,7 @@ START RequestId: XXXX	Version: $LATEST
   "timestamp": "XXXX-XX-XXTXX:XX:XX.XXXZ",
   "level": "ERROR",
   "requestId": "XXXX",
-  "message": "(node:XX) TimeoutOverflowWarning: XXXX does not fit into a 32-bit signed integer.\nTimeout duration was set to 1."
+  "message": "[dd.trace_id=XXXX dd.span_id=XXXX] (node:XX) TimeoutOverflowWarning: XXXX does not fit into a 32-bit signed integer.\nTimeout duration was set to 1."
 }
 {
   "traces": [
@@ -777,6 +777,12 @@ START RequestId: XXXX	Version: $LATEST
 END RequestId: XXXX
 REPORT RequestId: XXXX	Duration: XXXX ms
 START RequestId: XXXX	Version: $LATEST
+{
+  "timestamp": "XXXX-XX-XXTXX:XX:XX.XXXZ",
+  "level": "ERROR",
+  "requestId": "XXXX",
+  "message": "[dd.trace_id=XXXX dd.span_id=XXXX] (node:XX) TimeoutOverflowWarning: XXXX does not fit into a 32-bit signed integer.\nTimeout duration was set to 1."
+}
 {
   "e": XXXX,
   "m": "aws.lambda.enhanced.invocations",
@@ -792,12 +798,6 @@ START RequestId: XXXX	Version: $LATEST
   ],
   "v": 1
 }
-{
-  "timestamp": "XXXX-XX-XXTXX:XX:XX.XXXZ",
-  "level": "ERROR",
-  "requestId": "XXXX",
-  "message": "(node:XX) TimeoutOverflowWarning: XXXX does not fit into a 32-bit signed integer.\nTimeout duration was set to 1."
-}
 {
   "traces": [
     [
@@ -905,7 +905,7 @@ START RequestId: XXXX	Version: $LATEST
   "timestamp": "XXXX-XX-XXTXX:XX:XX.XXXZ",
   "level": "ERROR",
   "requestId": "XXXX",
-  "message": "(node:XX) TimeoutOverflowWarning: XXXX does not fit into a 32-bit signed integer.\nTimeout duration was set to 1."
+  "message": "[dd.trace_id=XXXX dd.span_id=XXXX] (node:XX) TimeoutOverflowWarning: XXXX does not fit into a 32-bit signed integer.\nTimeout duration was set to 1."
 }
 {
   "traces": [

src/handler.mjs

@@ -21,7 +21,7 @@ if (process.env.DD_TRACE_STARTUP_LOGS === undefined) {
 }
 
 if (getEnvValue("DD_TRACE_ENABLED", "true").toLowerCase() === "true") {
-  initTracer();
+  await initTracer();
 }
 
 const taskRootEnv = getEnvValue(lambdaTaskRootEnvVar, "");

src/handler.spec.ts

@@ -9,6 +9,7 @@ import * as zlib from "node:zlib";
 const fixtureDirectory = path.join(__dirname, "runtime", "fixtures");
 const handlerEntry = pathToFileURL(path.join(__dirname, "..", "dist", "handler.mjs")).href;
 const runnerPath = path.join(fixtureDirectory, "published-handler-runner.mjs");
+const loaderRegistrationSpyPath = path.join(fixtureDirectory, "loader-registration-spy.cjs");
 const tracePayloads: Buffer[] = [];
 
 let agent: http.Server;
@@ -104,10 +105,25 @@ async function runPublishedHandler(traceEnabled: boolean): Promise<unknown> {
   delete env.OTEL_METRICS_EXPORTER;
   delete env.OTEL_TRACES_EXPORTER;
 
-  const child = spawn(process.execPath, [runnerPath], {
-    env,
-    stdio: ["ignore", "pipe", "pipe", "ipc"],
-  });
+  const child = spawn(
+    process.execPath,
+    [
+      // Test-only preload that records whether Module.register or
+      // Module.registerHooks was used for ESM loader registration.
+      "--require",
+      loaderRegistrationSpyPath,
+      // Mirrors the Lambda Node bootstrap, which disables require(esm) unless
+      // NODE_OPTIONS contains --experimental-require-module.
+      ...(process.allowedNodeEnvironmentFlags.has("--experimental-require-module")
+        ? ["--no-experimental-require-module"]
+        : []),
+      runnerPath,
+    ],
+    {
+      env,
+      stdio: ["ignore", "pipe", "pipe", "ipc"],
+    },
+  );
   const closePromise = once(child, "close") as Promise<[number | null, NodeJS.Signals | null]>;
   const messagePromise = once(child, "message") as Promise<[unknown]>;
   let standardOutput = "";
@@ -162,10 +178,20 @@ async function runPublishedHandler(traceEnabled: boolean): Promise<unknown> {
 }
 
 const moduleWithRegister = Module as typeof Module & { register?: unknown };
+const moduleWithRegisterHooks = Module as typeof Module & { registerHooks?: unknown };
 const nodeMajor = Number(process.versions.node.split(".")[0]);
 const supportsDurableFixture = nodeMajor >= 22 && typeof moduleWithRegister.register === "function";
 const describeWithESMLoader = supportsDurableFixture ? describe : describe.skip;
 
+// tslint:disable-next-line:no-var-requires
+const { isSyncLoaderHookVersionSupported } = require("./runtime/module_importer") as {
+  isSyncLoaderHookVersionSupported(nodeVersion: string): boolean;
+};
+
+const syncHooksExpected =
+  isSyncLoaderHookVersionSupported(process.versions.node) &&
+  typeof moduleWithRegisterHooks.registerHooks === "function";
+
 describeWithESMLoader("published ESM handler", () => {
   jest.setTimeout(30_000);
 
@@ -192,7 +218,8 @@ describeWithESMLoader("published ESM handler", () => {
     const payload = Buffer.concat(tracePayloads);
 
     expect(message).toEqual({
-      registerLoaded: true,
+      registerLoaded: !syncHooksExpected,
+      registrations: [syncHooksExpected ? "registerHooks" : "register"],
       result: expect.objectContaining({ Status: "SUCCEEDED" }),
     });
     expect(payload.includes(Buffer.from("aws.lambda"))).toBe(true);
@@ -204,6 +231,7 @@ describeWithESMLoader("published ESM handler", () => {
 
     expect(message).toEqual({
       registerLoaded: false,
+      registrations: [],
       result: expect.objectContaining({ Status: "SUCCEEDED" }),
     });
     expect(tracePayloads).toHaveLength(0);

src/runtime/fixtures/loader-registration-spy.cjs

@@ -0,0 +1,27 @@
+"use strict";
+
+// Preload that mirrors how the tests observe loader registration. It wraps
+// Module.register and Module.registerHooks so the runner can report which
+// registration API dd-trace used. The file name intentionally contains no
+// "dd-trace" reference so esmLoaderAlreadyRegistered does not match it.
+const Module = require("node:module");
+
+globalThis.__ddLoaderRegistrations = [];
+
+const register = Module.register;
+if (typeof register === "function") {
+    Module.register = function (...args) {
+        globalThis.__ddLoaderRegistrations.push("register");
+        return register.apply(this, args);
+    };
+}
+
+const registerHooks = Module.registerHooks;
+if (typeof registerHooks === "function") {
+    Module.registerHooks = function (...args) {
+        globalThis.__ddLoaderRegistrations.push("registerHooks");
+        return registerHooks.apply(this, args);
+    };
+}
+
+Module.syncBuiltinESMExports();

src/runtime/fixtures/published-handler-runner.mjs

@@ -37,6 +37,7 @@ const result = await handler(
 const exitSignal = once(process, "message");
 process.send({
   registerLoaded: require.cache[registerPath] !== undefined,
+  registrations: globalThis.__ddLoaderRegistrations ?? [],
   result,
 });
 await exitSignal;