Add trace events support for Node.js-like event tracing

src/bun.js/VirtualMachine.zig

@@ -638,6 +638,9 @@ pub fn enterUWSLoop(this: *VirtualMachine) void {
 }
 
 pub fn onBeforeExit(this: *VirtualMachine) void {
+    const trace_events = @import("./node/trace_events_impl.zig");
+    trace_events.emitBeforeExit();
+
     this.exit_handler.dispatchOnBeforeExit();
     var dispatch = false;
     while (true) {
@@ -696,11 +699,16 @@ pub fn setEntryPointEvalResultCJS(this: *VirtualMachine, value: JSValue) callcon
 }
 
 pub fn onExit(this: *VirtualMachine) void {
+    const trace_events = @import("./node/trace_events_impl.zig");
+
     this.exit_handler.dispatchOnExit();
     this.is_shutting_down = true;
 
     const rare_data = this.rare_data orelse return;
     defer rare_data.cleanup_hooks.clearAndFree(bun.default_allocator);
+
+    trace_events.emitRunCleanup();
+
     // 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;
@@ -710,6 +718,8 @@ pub fn onExit(this: *VirtualMachine) void {
             hook.execute();
         }
     }
+
+    trace_events.emitAtExit();
 }
 
 extern fn Zig__GlobalObject__destructOnExit(*JSGlobalObject) void;

src/bun.js/api/Timer.zig

@@ -286,12 +286,20 @@ pub const All = struct {
         // Split into a separate variable to avoid increasing the size of the timespec type.
         var has_set_now: bool = false;
 
+        var has_timers = false;
         while (this.next(&has_set_now, &now)) |t| {
+            has_timers = true;
             switch (t.fire(&now, vm)) {
                 .disarm => {},
                 .rearm => {},
             }
         }
+
+        // Emit trace event if we processed any timers
+        if (has_timers) {
+            const trace_events = @import("../node/trace_events_impl.zig");
+            trace_events.emitRunTimers();
+        }
     }
 
     const TimeoutWarning = enum {

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

@@ -196,6 +196,13 @@ pub fn tickImmediateTasks(this: *EventLoop, virtual_machine: *VirtualMachine) vo
     this.immediate_tasks = this.next_immediate_tasks;
     this.next_immediate_tasks = .{};
 
+    // Emit trace event for running immediates
+    if (to_run_now.items.len > 0) {
+        const trace_events = @import("./node/trace_events_impl.zig");
+        trace_events.emitCheckImmediate();
+        trace_events.emitRunAndClearNativeImmediates();
+    }
+
     var exception_thrown = false;
     for (to_run_now.items) |task| {
         exception_thrown = task.runImmediateTask(virtual_machine);

src/bun.js/node/trace_events_impl.zig

@@ -0,0 +1,168 @@
+const std = @import("std");
+const bun = @import("bun");
+const JSC = bun.JSC;
+const VirtualMachine = JSC.VirtualMachine;
+
+extern "c" fn getpid() c_int;
+
+pub const TraceEvents = struct {
+    enabled: bool = false,
+    categories: []const u8 = "",
+    file: ?std.fs.File = null,
+    start_time: i64 = 0,
+    process_id: i32 = 0,
+    first_event: bool = true,
+
+    pub fn init(categories: []const u8) !TraceEvents {
+        if (categories.len == 0) {
+            return TraceEvents{};
+        }
+
+        // Create trace file in current directory
+        const file = try std.fs.cwd().createFile("node_trace.1.log", .{});
+
+        var self = TraceEvents{
+            .enabled = true,
+            .categories = categories,
+            .file = file,
+            .start_time = std.time.microTimestamp(),
+            .process_id = @intCast(getpid()),
+            .first_event = true,
+        };
+
+        // Write initial trace event format header
+        try self.writeHeader();
+
+        return self;
+    }
+
+    fn writeHeader(self: *TraceEvents) !void {
+        const file = self.file orelse return;
+        try file.writeAll("{\"traceEvents\":[");
+    }
+
+    pub fn deinit(self: *TraceEvents) void {
+        if (self.file) |file| {
+            // Write closing bracket
+            file.writeAll("\n]}\n") catch {};
+            file.close();
+            self.file = null;
+        }
+    }
+
+    pub fn emit(
+        self: *TraceEvents,
+        name: []const u8,
+        phase: u8,
+        timestamp: ?i64,
+    ) void {
+        if (!self.enabled) return;
+        const file = self.file orelse return;
+
+        const ts = timestamp orelse (std.time.microTimestamp() - self.start_time);
+
+        // Write comma if not first event
+        if (!self.first_event) {
+            file.writeAll(",") catch return;
+        } else {
+            self.first_event = false;
+        }
+
+        // Write trace event in Chrome trace format
+        var buf: [1024]u8 = undefined;
+        const event = std.fmt.bufPrint(&buf,
+            \\\n{{"name":"{s}","cat":"node.environment","ph":"{c}","pid":{},"tid":1,"ts":{}}}
+        , .{
+            name,
+            phase,
+            self.process_id,
+            ts,
+        }) catch return;
+
+        file.writeAll(event) catch return;
+    }
+
+    pub fn emitInstant(self: *TraceEvents, name: []const u8) void {
+        self.emit(name, 'I', null);
+    }
+
+    pub fn emitBegin(self: *TraceEvents, name: []const u8) void {
+        self.emit(name, 'B', null);
+    }
+
+    pub fn emitEnd(self: *TraceEvents, name: []const u8) void {
+        self.emit(name, 'E', null);
+    }
+};
+
+// Global instance
+var trace_events: ?TraceEvents = null;
+
+pub fn init(categories: []const u8) void {
+    if (trace_events != null) return;
+
+    trace_events = TraceEvents.init(categories) catch {
+        // Silently fail if we can't create trace file
+        return;
+    };
+}
+
+pub fn deinit() void {
+    if (trace_events) |*te| {
+        te.deinit();
+        trace_events = null;
+    }
+}
+
+pub fn emit(name: []const u8, phase: u8) void {
+    if (trace_events) |*te| {
+        te.emit(name, phase, null);
+    }
+}
+
+pub fn emitInstant(name: []const u8) void {
+    if (trace_events) |*te| {
+        te.emitInstant(name);
+    }
+}
+
+pub fn emitBegin(name: []const u8) void {
+    if (trace_events) |*te| {
+        te.emitBegin(name);
+    }
+}
+
+pub fn emitEnd(name: []const u8) void {
+    if (trace_events) |*te| {
+        te.emitEnd(name);
+    }
+}
+
+// Emit environment lifecycle events
+pub fn emitEnvironment() void {
+    emitInstant("Environment");
+}
+
+pub fn emitRunTimers() void {
+    emitInstant("RunTimers");
+}
+
+pub fn emitCheckImmediate() void {
+    emitInstant("CheckImmediate");
+}
+
+pub fn emitRunAndClearNativeImmediates() void {
+    emitInstant("RunAndClearNativeImmediates");
+}
+
+pub fn emitBeforeExit() void {
+    emitInstant("BeforeExit");
+}
+
+pub fn emitRunCleanup() void {
+    emitInstant("RunCleanup");
+}
+
+pub fn emitAtExit() void {
+    emitInstant("AtExit");
+}

src/bun_js.zig

@@ -36,6 +36,13 @@ pub const Run = struct {
         bun.JSC.initialize(false);
         bun.Analytics.Features.standalone_executable += 1;
 
+        // Initialize trace events if requested
+        if (ctx.runtime_options.trace_event_categories.len > 0) {
+            const trace_events = @import("./bun.js/node/trace_events_impl.zig");
+            trace_events.init(ctx.runtime_options.trace_event_categories);
+            trace_events.emitEnvironment();
+        }
+
         const graph_ptr = try bun.default_allocator.create(bun.StandaloneModuleGraph);
         graph_ptr.* = graph;
         graph_ptr.set();
@@ -177,6 +184,13 @@ pub const Run = struct {
 
         bun.JSC.initialize(ctx.runtime_options.eval.eval_and_print);
 
+        // Initialize trace events if requested
+        if (ctx.runtime_options.trace_event_categories.len > 0) {
+            const trace_events = @import("./bun.js/node/trace_events_impl.zig");
+            trace_events.init(ctx.runtime_options.trace_event_categories);
+            trace_events.emitEnvironment();
+        }
+
         js_ast.Expr.Data.Store.create();
         js_ast.Stmt.Data.Store.create();
         var arena = try Arena.init();
@@ -274,6 +288,13 @@ pub const Run = struct {
         vm.global.vm().holdAPILock(&run, callback);
     }
 
+    fn exit(this: *Run, code: bun.shell.ExitCode) noreturn {
+        this.vm.exit_handler.exit_code = code;
+        this.vm.exit_handler.dispatchOnBeforeExit();
+        this.vm.onExit();
+        this.vm.globalExit();
+    }
+
     fn onUnhandledRejectionBeforeClose(this: *JSC.VirtualMachine, _: *JSC.JSGlobalObject, value: JSC.JSValue) void {
         this.runErrorHandler(value, this.onUnhandledRejectionExceptionList);
         run.any_unhandled = true;
@@ -320,6 +341,14 @@ pub const Run = struct {
 
         var printed_sourcemap_warning_and_version = false;
 
+        defer {
+            // Clean up trace events when exiting
+            if (this.ctx.runtime_options.trace_event_categories.len > 0) {
+                const trace_events = @import("./bun.js/node/trace_events_impl.zig");
+                trace_events.deinit();
+            }
+        }
+
         if (vm.loadEntryPoint(this.entry_path)) |promise| {
             if (promise.status(vm.global.vm()) == .rejected) {
                 const handled = vm.uncaughtException(vm.global, promise.result(vm.global.vm()), true);
@@ -452,8 +481,8 @@ pub const Run = struct {
         vm.global.handleRejectedPromises();
         vm.onExit();
 
-        if (this.any_unhandled and !printed_sourcemap_warning_and_version) {
-            this.vm.exit_handler.exit_code = 1;
+        if (run.any_unhandled and !printed_sourcemap_warning_and_version) {
+            run.vm.exit_handler.exit_code = 1;
 
             bun.JSC.SavedSourceMap.MissingSourceMapNoteInfo.print();
 

src/cli.zig

@@ -237,6 +237,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 trace event recording for specified categories") catch unreachable,
     };
 
     const auto_or_run_params = [_]ParamType{
@@ -851,6 +852,9 @@ 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;
+            }
         }
 
         if (opts.port != null and opts.origin == null) {
@@ -1547,6 +1551,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;

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);
+  }));
+}

trace-test-args.js

@@ -0,0 +1,20 @@
+const cp = require("child_process");
+const fs = require("fs");
+
+// Create a child script
+fs.writeFileSync(
+  "child-args.js",
+  `
+console.log('process.execArgv:', process.execArgv);
+console.log('process.argv:', process.argv);
+`,
+);
+
+console.log("Testing fork with execArgv...");
+const proc = cp.fork("./child-args.js", ["arg1", "arg2"], {
+  execArgv: ["--trace-event-categories", "node.environment", "--no-warnings"],
+});
+
+proc.on("exit", () => {
+  fs.unlinkSync("child-args.js");
+});

trace-test-fork.js

@@ -0,0 +1,36 @@
+const cp = require("child_process");
+const fs = require("fs");
+const path = require("path");
+
+const tmpdir = path.join("/tmp", "trace-test-fork-" + Date.now());
+fs.mkdirSync(tmpdir, { recursive: true });
+
+console.log("Running child in:", tmpdir);
+
+// Create a child script file
+const childScript = path.join(tmpdir, "child.js");
+fs.writeFileSync(
+  childScript,
+  `
+console.log('Child process started in:', process.cwd());
+setTimeout(() => {}, 1);
+setImmediate(() => {});
+`,
+);
+
+const proc = cp.fork(childScript, [], {
+  cwd: tmpdir,
+  execArgv: ["--trace-event-categories", "node.environment"],
+});
+
+proc.on("exit", () => {
+  console.log("Child exited");
+  const files = fs.readdirSync(tmpdir);
+  console.log("Files in tmpdir:", files);
+
+  // Also check parent directory
+  const parentFiles = fs.readdirSync(".").filter(f => f.startsWith("node_trace"));
+  console.log("Trace files in parent:", parentFiles);
+
+  fs.rmSync(tmpdir, { recursive: true });
+});

trace-test.js

@@ -0,0 +1,26 @@
+const cp = require("child_process");
+const fs = require("fs");
+const path = require("path");
+
+const tmpdir = path.join("/tmp", "trace-test-" + Date.now());
+fs.mkdirSync(tmpdir, { recursive: true });
+
+console.log("Running child in:", tmpdir);
+
+const proc = cp.spawn(
+  process.execPath,
+  ["--trace-event-categories", "node.environment", "-e", "setTimeout(() => {}, 1); setImmediate(() => {})"],
+  { cwd: tmpdir },
+);
+
+proc.on("exit", () => {
+  console.log("Child exited");
+  const files = fs.readdirSync(tmpdir);
+  console.log("Files in tmpdir:", files);
+
+  // Also check parent directory
+  const parentFiles = fs.readdirSync(".").filter(f => f.startsWith("node_trace"));
+  console.log("Trace files in parent:", parentFiles);
+
+  fs.rmSync(tmpdir, { recursive: true });
+});