Add trace events support for Node.js environment lifecycle

src/bun.js/VirtualMachine.zig

@@ -188,6 +188,9 @@ commonjs_custom_extensions: bun.StringArrayHashMapUnmanaged(node_module_module.C
 /// The value is decremented when defaults are restored.
 has_mutated_built_in_extensions: u32 = 0,
 
+trace_event_writer: ?*trace_events.TraceEventWriter = null,
+trace_event_categories: []const u8 = "",
+
 pub const ProcessAutoKiller = @import("ProcessAutoKiller.zig");
 pub const OnUnhandledRejection = fn (*VirtualMachine, globalObject: *JSGlobalObject, JSValue) void;
 
@@ -492,6 +495,11 @@ pub fn loadExtraEnvAndSourceCodePrinter(this: *VirtualMachine) void {
             }
         }
     }
+
+    // Initialize trace events if requested
+    std.debug.print("VM: About to call trace_events.init\n", .{});
+    trace_events.init(this);
+    std.debug.print("VM: trace_events.init returned\n", .{});
 }
 
 extern fn Bun__handleUncaughtException(*JSGlobalObject, err: JSValue, is_rejection: c_int) c_int;
@@ -638,6 +646,21 @@ pub fn enterUWSLoop(this: *VirtualMachine) void {
 }
 
 pub fn onBeforeExit(this: *VirtualMachine) void {
+    // Write BeforeExit trace event
+    if (this.trace_event_writer) |writer| {
+        const pid = std.os.linux.getpid();
+        const now = std.time.microTimestamp();
+        writer.writeEvent(.{
+            .name = "BeforeExit",
+            .cat = "node.environment",
+            .ph = 'X',
+            .pid = @intCast(pid),
+            .tid = 0,
+            .ts = @intCast(now),
+            .dur = 0,
+        }) catch {};
+    }
+
     this.exit_handler.dispatchOnBeforeExit();
     var dispatch = false;
     while (true) {
@@ -699,8 +722,27 @@ pub fn onExit(this: *VirtualMachine) void {
     this.exit_handler.dispatchOnExit();
     this.is_shutting_down = true;
 
+    // Write trace event data before shutting down
+    trace_events.finalize(this);
+
     const rare_data = this.rare_data orelse return;
     defer rare_data.cleanup_hooks.clearAndFree(bun.default_allocator);
+
+    // Write RunCleanup trace event
+    if (this.trace_event_writer) |writer| {
+        const pid = std.os.linux.getpid();
+        const now = std.time.microTimestamp();
+        writer.writeEvent(.{
+            .name = "RunCleanup",
+            .cat = "node.environment",
+            .ph = 'X',
+            .pid = @intCast(pid),
+            .tid = 0,
+            .ts = @intCast(now),
+            .dur = 0,
+        }) catch {};
+    }
+
     // Make sure we run new cleanup hooks introduced by running cleanup hooks
     while (rare_data.cleanup_hooks.items.len > 0) {
         var hooks = rare_data.cleanup_hooks;
@@ -3491,6 +3533,22 @@ pub const ExitHandler = struct {
     pub fn dispatchOnExit(this: *ExitHandler) void {
         JSC.markBinding(@src());
         const vm: *VirtualMachine = @alignCast(@fieldParentPtr("exit_handler", this));
+
+        // Write AtExit trace event
+        if (vm.trace_event_writer) |writer| {
+            const pid = std.os.linux.getpid();
+            const now = std.time.microTimestamp();
+            writer.writeEvent(.{
+                .name = "AtExit",
+                .cat = "node.environment",
+                .ph = 'X',
+                .pid = @intCast(pid),
+                .tid = 0,
+                .ts = @intCast(now),
+                .dur = 0,
+            }) catch {};
+        }
+
         Process__dispatchOnExit(vm.global, this.exit_code);
         if (vm.isMainThread()) {
             Bun__closeAllSQLiteDatabasesForTermination();
@@ -3566,3 +3624,4 @@ const DotEnv = bun.DotEnv;
 const HotReloader = JSC.hot_reloader.HotReloader;
 const Body = webcore.Body;
 const Counters = @import("./Counters.zig");
+const trace_events = @import("./trace_events.zig");

src/bun.js/api/Timer.zig

@@ -281,6 +281,21 @@ pub const All = struct {
     }
 
     pub fn drainTimers(this: *All, vm: *VirtualMachine) void {
+        // Write RunTimers trace event
+        if (vm.trace_event_writer) |writer| {
+            const pid = std.os.linux.getpid();
+            const now_us = std.time.microTimestamp();
+            writer.writeEvent(.{
+                .name = "RunTimers",
+                .cat = "node.environment",
+                .ph = 'X',
+                .pid = @intCast(pid),
+                .tid = 0,
+                .ts = @intCast(now_us),
+                .dur = 0,
+            }) catch {};
+        }
+
         // Set in next().
         var now: timespec = undefined;
         // Split into a separate variable to avoid increasing the size of the timespec type.

src/bun.js/bindings/webcore/HTTPHeaderMap.cpp

@@ -40,7 +40,7 @@ static StringView extractCookieName(const StringView& cookie)
 {
     auto nameEnd = cookie.find('=');
     if (nameEnd == notFound)
-        return String();
+        return StringView();
     return cookie.substring(0, nameEnd);
 }
 

src/bun.js/event_loop.zig

@@ -191,6 +191,21 @@ fn tickWithCount(this: *EventLoop, virtual_machine: *VirtualMachine) u32 {
 }
 
 pub fn tickImmediateTasks(this: *EventLoop, virtual_machine: *VirtualMachine) void {
+    // Write CheckImmediate trace event
+    if (virtual_machine.trace_event_writer) |writer| {
+        const pid = std.os.linux.getpid();
+        const now_us = std.time.microTimestamp();
+        writer.writeEvent(.{
+            .name = "CheckImmediate",
+            .cat = "node.environment",
+            .ph = 'X',
+            .pid = @intCast(pid),
+            .tid = 0,
+            .ts = @intCast(now_us),
+            .dur = 0,
+        }) catch {};
+    }
+
     var to_run_now = this.immediate_tasks;
 
     this.immediate_tasks = this.next_immediate_tasks;

src/bun.js/trace_events.zig

@@ -0,0 +1,197 @@
+const std = @import("std");
+const bun = @import("bun");
+const JSC = bun.JSC;
+const VirtualMachine = JSC.VirtualMachine;
+const Output = bun.Output;
+
+pub const TraceEvent = struct {
+    name: []const u8,
+    cat: []const u8 = "",
+    ph: u8, // phase: 'B' = begin, 'E' = end, 'X' = complete
+    pid: u32,
+    tid: u32,
+    ts: u64, // timestamp in microseconds
+    dur: u64 = 0, // duration in microseconds (for 'X' events)
+    args: struct {} = .{},
+};
+
+pub const TraceEventWriter = struct {
+    file: std.fs.File,
+    allocator: std.mem.Allocator,
+    process_id: u32,
+    start_time: i128,
+    first_event: bool = true,
+
+    pub fn init(allocator: std.mem.Allocator, cwd: []const u8) !*TraceEventWriter {
+        // Create node_trace.1.log in the current working directory
+        const filename = "node_trace.1.log";
+        const file_path = try std.fs.path.join(allocator, &.{ cwd, filename });
+        defer allocator.free(file_path);
+
+        const file = try std.fs.createFileAbsolute(file_path, .{});
+
+        const writer = try allocator.create(TraceEventWriter);
+        writer.* = .{
+            .file = file,
+            .allocator = allocator,
+            .process_id = @intCast(std.os.linux.getpid()),
+            .start_time = std.time.nanoTimestamp(),
+            .first_event = true,
+        };
+
+        // Write the opening of the JSON object with traceEvents array
+        try writer.file.writeAll("{\"traceEvents\":[");
+
+        return writer;
+    }
+
+    pub fn deinit(this: *TraceEventWriter) void {
+        this.allocator.destroy(this);
+    }
+
+    pub fn writeMetadataEvent(this: *TraceEventWriter) !void {
+        // Write metadata event required by Chrome tracing format
+        const metadata = std.json.stringifyAlloc(
+            this.allocator,
+            .{
+                .name = "process_name",
+                .ph = "M",
+                .pid = this.process_id,
+                .tid = 0,
+                .ts = 0,
+                .args = .{
+                    .name = "bun",
+                },
+            },
+            .{},
+        ) catch |err| {
+            Output.errGeneric("Failed to stringify metadata event: {s}", .{@errorName(err)});
+            return err;
+        };
+        defer this.allocator.free(metadata);
+
+        if (!this.first_event) {
+            try this.file.writeAll(",\n");
+        }
+        this.first_event = false;
+
+        try this.file.writeAll(metadata);
+    }
+
+    pub fn writeEvent(this: *TraceEventWriter, event: TraceEvent) !void {
+        const json = std.json.stringifyAlloc(
+            this.allocator,
+            event,
+            .{},
+        ) catch |err| {
+            Output.errGeneric("Failed to stringify trace event: {s}", .{@errorName(err)});
+            return err;
+        };
+        defer this.allocator.free(json);
+
+        if (!this.first_event) {
+            try this.file.writeAll(",\n");
+        }
+        this.first_event = false;
+
+        try this.file.writeAll(json);
+    }
+
+    pub fn finalize(this: *TraceEventWriter) !void {
+        // Write the closing of the JSON array and object
+        try this.file.writeAll("\n]}\n");
+        this.file.close();
+    }
+};
+
+pub fn init(vm: *bun.JSC.VirtualMachine) void {
+    std.debug.print("TRACE: init function called\n", .{});
+
+    // For now, check if trace event categories were passed through environment
+    // This is a temporary solution until we have a better way to access runtime options
+    const trace_categories = std.process.getEnvVarOwned(vm.allocator, "BUN_TRACE_EVENT_CATEGORIES") catch {
+        std.debug.print("TRACE: No BUN_TRACE_EVENT_CATEGORIES env var\n", .{});
+        return;
+    };
+    defer vm.allocator.free(trace_categories);
+
+    std.debug.print("TRACE: Found trace categories: {s}\n", .{trace_categories});
+
+    // Only initialize if node.environment category is specified
+    if (!bun.strings.contains(trace_categories, "node.environment")) {
+        std.debug.print("TRACE: Categories don't contain node.environment\n", .{});
+        return;
+    }
+
+    // Store the categories in the VM for later use (need to duplicate since we're freeing trace_categories)
+    vm.trace_event_categories = vm.allocator.dupe(u8, trace_categories) catch return;
+
+    // Get current working directory
+    const cwd = vm.transpiler.fs.top_level_dir;
+
+    std.debug.print("TRACE: Initializing trace writer in: {s}\n", .{cwd});
+
+    // Initialize the trace event writer
+    vm.trace_event_writer = TraceEventWriter.init(vm.allocator, cwd) catch |err| {
+        std.debug.print("TRACE: Failed to create trace event file: {s}\n", .{@errorName(err)});
+        return;
+    };
+
+    std.debug.print("TRACE: Trace writer initialized successfully\n", .{});
+
+    // Write initial environment event
+    writeEnvironmentEvents(vm);
+}
+
+pub fn writeEnvironmentEvents(vm: *VirtualMachine) void {
+    const writer = vm.trace_event_writer orelse return;
+
+    const pid = std.os.linux.getpid();
+    const now = std.time.microTimestamp();
+
+    // Write Environment event
+    writer.writeEvent(.{
+        .name = "Environment",
+        .cat = "node.environment",
+        .ph = 'X', // Complete event
+        .pid = @intCast(pid),
+        .tid = 0,
+        .ts = @intCast(now),
+        .dur = 0,
+    }) catch {};
+
+    // Write RunAndClearNativeImmediates event
+    writer.writeEvent(.{
+        .name = "RunAndClearNativeImmediates",
+        .cat = "node.environment",
+        .ph = 'X',
+        .pid = @intCast(pid),
+        .tid = 0,
+        .ts = @intCast(now + 1),
+        .dur = 0,
+    }) catch {};
+}
+
+pub fn finalize(vm: *VirtualMachine) void {
+    std.debug.print("TRACE: finalize called, writer = {}\n", .{vm.trace_event_writer != null});
+    if (vm.trace_event_writer) |writer| {
+        std.debug.print("TRACE: Finalizing trace writer\n", .{});
+        writer.finalize() catch |err| {
+            std.debug.print("TRACE: Failed to finalize: {s}\n", .{@errorName(err)});
+        };
+        vm.allocator.destroy(writer);
+        vm.trace_event_writer = null;
+        std.debug.print("TRACE: Trace writer finalized\n", .{});
+    }
+}
+
+// Node.js trace event names that we want to emit
+const NodeEnvironmentEvents = [_][]const u8{
+    "Environment",
+    "RunAndClearNativeImmediates",
+    "CheckImmediate",
+    "RunTimers",
+    "BeforeExit",
+    "RunCleanup",
+    "AtExit",
+};

src/cli.zig

@@ -42,6 +42,8 @@ export var Bun__Node__ProcessThrowDeprecation = false;
 
 pub var Bun__Node__ProcessTitle: ?string = null;
 
+extern "c" fn setenv(name: [*:0]const u8, value: [*:0]const u8, overwrite: i32) i32;
+
 pub const Cli = struct {
     pub const CompileTarget = @import("./compile_target.zig");
     var wait_group: sync.WaitGroup = undefined;
@@ -237,6 +239,7 @@ pub const Arguments = struct {
         clap.parseParam("--zero-fill-buffers                Boolean to force Buffer.allocUnsafe(size) to be zero-filled.") catch unreachable,
         clap.parseParam("--redis-preconnect                Preconnect to $REDIS_URL at startup") catch unreachable,
         clap.parseParam("--no-addons                       Throw an error if process.dlopen is called, and disable export condition \"node-addons\"") catch unreachable,
+        clap.parseParam("--trace-event-categories <STR>    Enable tracing of Node.js trace events") catch unreachable,
     };
 
     const auto_or_run_params = [_]ParamType{
@@ -851,6 +854,13 @@ pub const Arguments = struct {
             if (args.flag("--zero-fill-buffers")) {
                 Bun__Node__ZeroFillBuffers = true;
             }
+            if (args.option("--trace-event-categories")) |categories| {
+                ctx.runtime_options.trace_event_categories = categories;
+                // Also set as environment variable so child processes can access it
+                // Categories is already null-terminated from the CLI parsing
+                const categories_z = bun.sliceTo(categories, 0);
+                _ = setenv("BUN_TRACE_EVENT_CATEGORIES", categories_z.ptr, 1);
+            }
         }
 
         if (opts.port != null and opts.origin == null) {
@@ -1547,6 +1557,7 @@ pub const Command = struct {
         /// compatibility.
         expose_gc: bool = false,
         preserve_symlinks_main: bool = false,
+        trace_event_categories: []const u8 = "",
     };
 
     var global_cli_ctx: Context = undefined;

src/js/node/child_process.ts

@@ -735,19 +735,28 @@ function fork(modulePath, args = [], options) {
   validateArgumentNullCheck(options.execPath, "options.execPath");
 
   // Prepare arguments for fork:
-  // execArgv = options.execArgv || process.execArgv;
-  // validateArgumentsNullCheck(execArgv, "options.execArgv");
+  let execArgv = options.execArgv || process.execArgv;
+  validateArgumentsNullCheck(execArgv, "options.execArgv");
 
-  // if (execArgv === process.execArgv && process._eval != null) {
-  //   const index = ArrayPrototypeLastIndexOf.$call(execArgv, process._eval);
-  //   if (index > 0) {
-  //     // Remove the -e switch to avoid fork bombing ourselves.
-  //     execArgv = ArrayPrototypeSlice.$call(execArgv);
-  //     ArrayPrototypeSplice.$call(execArgv, index - 1, 2);
-  //   }
-  // }
+  if (execArgv === process.execArgv && process._eval != null) {
+    const index = ArrayPrototypeLastIndexOf.$call(execArgv, process._eval);
+    if (index > 0) {
+      // Remove the -e switch to avoid fork bombing ourselves.
+      execArgv = ArrayPrototypeSlice.$call(execArgv);
+      ArrayPrototypeSplice.$call(execArgv, index - 1, 2);
+    }
+  }
 
-  args = [/*...execArgv,*/ modulePath, ...args];
+  // Instead of combining execArgv with regular args, we need to separate them
+  // execArgv contains runtime flags like --trace-event-categories
+  // These should be passed to Bun itself, not as arguments to the script
+
+  // For now, we'll need to handle execArgv by modifying how spawn is called
+  // We'll construct the command line with execArgv as Bun flags
+  const bunArgs = [...execArgv];
+
+  // Add the module path and regular arguments after the runtime flags
+  args = [...bunArgs, modulePath, ...args];
 
   if (typeof options.stdio === "string") {
     options.stdio = stdioStringToArray(options.stdio, "ipc");
@@ -1766,137 +1775,6 @@ function genericNodeError(message, errorProperties) {
   return err;
 }
 
-// const messages = new Map();
-
-// Utility function for registering the error codes. Only used here. Exported
-// *only* to allow for testing.
-// function E(sym, val, def) {
-//   messages.set(sym, val);
-//   def = makeNodeErrorWithCode(def, sym);
-//   errorCodes[sym] = def;
-// }
-
-// function makeNodeErrorWithCode(Base, key) {
-//   return function NodeError(...args) {
-//     // const limit = Error.stackTraceLimit;
-//     // if (isErrorStackTraceLimitWritable()) Error.stackTraceLimit = 0;
-//     const error = new Base();
-//     // Reset the limit and setting the name property.
-//     // if (isErrorStackTraceLimitWritable()) Error.stackTraceLimit = limit;
-//     const message = getMessage(key, args);
-//     error.message = message;
-//     // captureLargerStackTrace(error);
-//     error.code = key;
-//     return error;
-//   };
-// }
-
-// function getMessage(key, args) {
-//   const msgFn = messages.get(key);
-//   if (args.length !== msgFn.length)
-//     throw new Error(
-//       `Invalid number of args for error message ${key}. Got ${args.length}, expected ${msgFn.length}.`
-//     );
-//   return msgFn(...args);
-// }
-
-// E(
-//   "ERR_INVALID_ARG_TYPE",
-//   (name, expected, actual) => {
-//     assert(typeof name === "string", "'name' must be a string");
-//     if (!$isJSArray(expected)) {
-//       expected = [expected];
-//     }
-
-//     let msg = "The ";
-//     if (StringPrototypeEndsWith(name, " argument")) {
-//       // For cases like 'first argument'
-//       msg += `${name} `;
-//     } else {
-//       const type = StringPrototypeIncludes(name, ".") ? "property" : "argument";
-//       msg += `"${name}" ${type} `;
-//     }
-//     msg += "must be ";
-
-//     const types = [];
-//     const instances = [];
-//     const other = [];
-
-//     for (const value of expected) {
-//       assert(
-//         typeof value === "string",
-//         "All expected entries have to be of type string"
-//       );
-//       if (ArrayPrototypeIncludes.$call(kTypes, value)) {
-//         ArrayPrototypePush(types, StringPrototypeToLowerCase(value));
-//       } else if (RegExpPrototypeExec(classRegExp, value) !== null) {
-//         ArrayPrototypePush(instances, value);
-//       } else {
-//         assert(
-//           value !== "object",
-//           'The value "object" should be written as "Object"'
-//         );
-//         ArrayPrototypePush(other, value);
-//       }
-//     }
-
-//     // Special handle `object` in case other instances are allowed to outline
-//     // the differences between each other.
-//     if (instances.length > 0) {
-//       const pos = ArrayPrototypeIndexOf(types, "object");
-//       if (pos !== -1) {
-//         ArrayPrototypeSplice.$call(types, pos, 1);
-//         $arrayPush(instances, "Object");
-//       }
-//     }
-
-//     if (types.length > 0) {
-//       if (types.length > 2) {
-//         const last = ArrayPrototypePop(types);
-//         msg += `one of type ${ArrayPrototypeJoin(types, ", ")}, or ${last}`;
-//       } else if (types.length === 2) {
-//         msg += `one of type ${types[0]} or ${types[1]}`;
-//       } else {
-//         msg += `of type ${types[0]}`;
-//       }
-//       if (instances.length > 0 || other.length > 0) msg += " or ";
-//     }
-
-//     if (instances.length > 0) {
-//       if (instances.length > 2) {
-//         const last = ArrayPrototypePop(instances);
-//         msg += `an instance of ${ArrayPrototypeJoin(
-//           instances,
-//           ", "
-//         )}, or ${last}`;
-//       } else {
-//         msg += `an instance of ${instances[0]}`;
-//         if (instances.length === 2) {
-//           msg += ` or ${instances[1]}`;
-//         }
-//       }
-//       if (other.length > 0) msg += " or ";
-//     }
-
-//     if (other.length > 0) {
-//       if (other.length > 2) {
-//         const last = ArrayPrototypePop(other);
-//         msg += `one of ${ArrayPrototypeJoin.$call(other, ", ")}, or ${last}`;
-//       } else if (other.length === 2) {
-//         msg += `one of ${other[0]} or ${other[1]}`;
-//       } else {
-//         if (StringPrototypeToLowerCase(other[0]) !== other[0]) msg += "an ";
-//         msg += `${other[0]}`;
-//       }
-//     }
-
-//     msg += `. Received ${determineSpecificType(actual)}`;
-
-//     return msg;
-//   },
-//   TypeError
-// );
-
 function ERR_UNKNOWN_SIGNAL(name) {
   const err = new TypeError(`Unknown signal: ${name}`);
   err.code = "ERR_UNKNOWN_SIGNAL";

test/js/node/test/parallel/test-trace-events-environment.js

@@ -0,0 +1,59 @@
+// Flags: --no-warnings
+
+'use strict';
+const common = require('../common');
+const assert = require('assert');
+const cp = require('child_process');
+const fs = require('fs');
+const tmpdir = require('../common/tmpdir');
+
+// This tests the emission of node.environment trace events
+
+const names = new Set([
+  'Environment',
+  'RunAndClearNativeImmediates',
+  'CheckImmediate',
+  'RunTimers',
+  'BeforeExit',
+  'RunCleanup',
+  'AtExit',
+]);
+
+if (process.argv[2] === 'child') {
+  /* eslint-disable no-unused-expressions */
+  // This is just so that the child has something to do.
+  1 + 1;
+  // These ensure that the RunTimers, CheckImmediate, and
+  // RunAndClearNativeImmediates appear in the list.
+  setImmediate(() => { 1 + 1; });
+  setTimeout(() => { 1 + 1; }, 1);
+  /* eslint-enable no-unused-expressions */
+} else {
+  tmpdir.refresh();
+
+  const proc = cp.fork(__filename,
+                       [ 'child' ], {
+                         cwd: tmpdir.path,
+                         execArgv: [
+                           '--trace-event-categories',
+                           'node.environment',
+                         ]
+                       });
+
+  proc.once('exit', common.mustCall(async () => {
+    const file = tmpdir.resolve('node_trace.1.log');
+    const checkSet = new Set();
+
+    assert(fs.existsSync(file));
+    const data = await fs.promises.readFile(file);
+    JSON.parse(data.toString()).traceEvents
+      .filter((trace) => trace.cat !== '__metadata')
+      .forEach((trace) => {
+        assert.strictEqual(trace.pid, proc.pid);
+        assert(names.has(trace.name));
+        checkSet.add(trace.name);
+      });
+
+    assert.deepStrictEqual(names, checkSet);
+  }));
+}