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

src/bun.js/VirtualMachine.zig

@@ -638,6 +638,9 @@ pub fn enterUWSLoop(this: *VirtualMachine) void {
 }
 
 pub fn onBeforeExit(this: *VirtualMachine) void {
+    const TraceEvents = @import("./node/trace_events.zig");
+    TraceEvents.emitInstant("BeforeExit");
+
     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 TraceEvents = @import("./node/trace_events.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);
+
+    TraceEvents.emitInstant("RunCleanup");
+
     // 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,11 +718,16 @@ pub fn onExit(this: *VirtualMachine) void {
             hook.execute();
         }
     }
+
+    TraceEvents.emitInstant("AtExit");
 }
 
 extern fn Zig__GlobalObject__destructOnExit(*JSGlobalObject) void;
 
 pub fn globalExit(this: *VirtualMachine) noreturn {
+    const TraceEvents = @import("./node/trace_events.zig");
+    TraceEvents.finalize();
+
     if (this.destruct_main_thread_on_exit and this.is_main_thread) {
         Zig__GlobalObject__destructOnExit(this.global);
         this.deinit();

src/bun.js/event_loop.zig

@@ -1,4 +1,5 @@
 const EventLoop = @This();
+const TraceEvents = @import("./node/trace_events.zig");
 
 tasks: Queue = undefined,
 
@@ -196,6 +197,11 @@ pub fn tickImmediateTasks(this: *EventLoop, virtual_machine: *VirtualMachine) vo
     this.immediate_tasks = this.next_immediate_tasks;
     this.next_immediate_tasks = .{};
 
+    if (to_run_now.items.len > 0) {
+        TraceEvents.emitInstant("RunAndClearNativeImmediates");
+        TraceEvents.emitInstant("CheckImmediate");
+    }
+
     var exception_thrown = false;
     for (to_run_now.items) |task| {
         exception_thrown = task.runImmediateTask(virtual_machine);
@@ -364,6 +370,7 @@ pub fn autoTick(this: *EventLoop) void {
 
     if (Environment.isPosix) {
         ctx.timer.drainTimers(ctx);
+        TraceEvents.emitInstant("RunTimers");
     }
 
     ctx.onAfterEventLoop();

src/bun.js/node/trace_events.zig

@@ -0,0 +1,183 @@
+const std = @import("std");
+const bun = @import("root").bun;
+const JSC = bun.JSC;
+const VirtualMachine = JSC.VirtualMachine;
+const json = std.json;
+
+pub const TraceEvents = struct {
+    enabled: bool = false,
+    categories: []const []const u8 = &.{},
+    file: ?std.fs.File = null,
+    event_count: usize = 0,
+    start_time: i64 = 0,
+    vm: *VirtualMachine = undefined,
+    allocator: std.mem.Allocator = undefined,
+    write_mutex: bun.Mutex = .{},
+
+    const TraceEvent = struct {
+        name: []const u8,
+        cat: []const u8,
+        ph: []const u8, // phase
+        pid: i32,
+        tid: i32,
+        ts: i64, // timestamp in microseconds
+        dur: ?i64 = null, // duration for complete events
+        args: ?json.ObjectMap = null,
+    };
+
+    const TraceFile = struct {
+        traceEvents: []const TraceEvent,
+        metadata: struct {
+            @"node.versions": struct {
+                node: []const u8,
+                v8: []const u8,
+            },
+        },
+    };
+
+    pub fn init(vm: *VirtualMachine, categories: []const []const u8) !*TraceEvents {
+        const allocator = bun.default_allocator;
+        var self = try allocator.create(TraceEvents);
+
+        self.* = .{
+            .enabled = categories.len > 0,
+            .categories = categories,
+            .vm = vm,
+            .allocator = allocator,
+            .start_time = std.time.microTimestamp(),
+        };
+
+        if (self.enabled) {
+            // Check if any of the categories match "node.environment"
+            var has_environment = false;
+            for (categories) |cat| {
+                if (bun.strings.eql(cat, "node.environment")) {
+                    has_environment = true;
+                    break;
+                }
+            }
+
+            if (has_environment) {
+                try self.openFile();
+            }
+        }
+
+        return self;
+    }
+
+    fn openFile(self: *TraceEvents) !void {
+        const cwd = self.vm.transpiler.options.output_dir orelse try bun.getcwdAlloc(self.allocator);
+        defer if (self.vm.transpiler.options.output_dir == null) self.allocator.free(cwd);
+        const filename = try std.fmt.allocPrint(self.allocator, "{s}/node_trace.1.log", .{cwd});
+        defer self.allocator.free(filename);
+
+        self.file = try std.fs.createFileAbsolute(filename, .{ .truncate = true });
+
+        // Write initial array opening
+        _ = try self.file.?.write("{\n");
+    }
+
+    pub fn emit(self: *TraceEvents, name: []const u8, cat: []const u8, phase: []const u8) void {
+        if (!self.enabled or self.file == null) return;
+
+        self.write_mutex.lock();
+        defer self.write_mutex.unlock();
+
+        const ts = std.time.microTimestamp() - self.start_time;
+        const pid = @as(i32, @intCast(std.os.getpid()));
+        const tid = @as(i32, @intCast(std.Thread.getCurrentId()));
+
+        const event = TraceEvent{
+            .name = name,
+            .cat = cat,
+            .ph = phase,
+            .pid = pid,
+            .tid = tid,
+            .ts = ts,
+        };
+
+        self.writeEvent(event) catch {};
+        self.event_count += 1;
+    }
+
+    fn writeEvent(self: *TraceEvents, event: TraceEvent) !void {
+        var buffer: [4096]u8 = undefined;
+        var stream = std.io.fixedBufferStream(&buffer);
+        const writer = stream.writer();
+
+        if (self.event_count == 0) {
+            try writer.writeAll("  \"traceEvents\": [\n");
+        } else {
+            try writer.writeAll(",\n");
+        }
+
+        try writer.writeAll("    {");
+        try writer.print("\"name\":\"{s}\",", .{event.name});
+        try writer.print("\"cat\":\"{s}\",", .{event.cat});
+        try writer.print("\"ph\":\"{s}\",", .{event.ph});
+        try writer.print("\"pid\":{d},", .{event.pid});
+        try writer.print("\"tid\":{d},", .{event.tid});
+        try writer.print("\"ts\":{d}", .{event.ts});
+        try writer.writeAll("}");
+
+        _ = try self.file.?.write(stream.getWritten());
+    }
+
+    pub fn finalize(self: *TraceEvents) void {
+        if (self.file) |file| {
+            self.write_mutex.lock();
+            defer self.write_mutex.unlock();
+
+            // Close the traceEvents array and add metadata
+            const closer =
+                \\
+                \\  ],
+                \\  "metadata": {
+                \\    "node.versions": {
+                \\      "node": "22.11.0",
+                \\      "v8": "12.4.254.14-node.19"
+                \\    }
+                \\  }
+                \\}
+            ;
+            _ = file.write(closer) catch {};
+            file.close();
+        }
+    }
+
+    pub fn deinit(self: *TraceEvents) void {
+        self.finalize();
+        self.allocator.destroy(self);
+    }
+};
+
+// Global trace events instance
+var trace_events: ?*TraceEvents = null;
+
+pub fn initialize(vm: *VirtualMachine, categories: []const []const u8) void {
+    if (trace_events != null) return;
+
+    trace_events = TraceEvents.init(vm, categories) catch null;
+}
+
+pub fn emit(name: []const u8, cat: []const u8, phase: []const u8) void {
+    if (trace_events) |events| {
+        events.emit(name, cat, phase);
+    }
+}
+
+pub fn finalize() void {
+    if (trace_events) |events| {
+        events.deinit();
+        trace_events = null;
+    }
+}
+
+// Convenience functions for common event types
+pub fn emitInstant(name: []const u8) void {
+    emit(name, "node.environment", "I");
+}
+
+pub fn emitComplete(name: []const u8) void {
+    emit(name, "node.environment", "X");
+}

src/bun_js.zig

@@ -114,6 +114,12 @@ pub const Run = struct {
 
         doPreconnect(ctx.runtime_options.preconnect);
 
+        // Initialize trace events if enabled
+        if (ctx.runtime_options.trace_event_categories.len > 0) {
+            @import("bun.js/node/trace_events.zig").initialize(vm, ctx.runtime_options.trace_event_categories);
+            @import("bun.js/node/trace_events.zig").emitInstant("Environment");
+        }
+
         const callback = OpaqueWrap(Run, Run.start);
         vm.global.vm().holdAPILock(&run, callback);
     }
@@ -268,6 +274,12 @@ pub const Run = struct {
 
         doPreconnect(ctx.runtime_options.preconnect);
 
+        // Initialize trace events if enabled
+        if (ctx.runtime_options.trace_event_categories.len > 0) {
+            @import("bun.js/node/trace_events.zig").initialize(vm, ctx.runtime_options.trace_event_categories);
+            @import("bun.js/node/trace_events.zig").emitInstant("Environment");
+        }
+
         vm.main_is_html_entrypoint = (loader orelse vm.transpiler.options.loader(std.fs.path.extension(entry_path))) == .html;
 
         const callback = OpaqueWrap(Run, Run.start);

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 events for the specified categories") catch unreachable,
     };
 
     const auto_or_run_params = [_]ParamType{
@@ -851,6 +852,10 @@ pub const Arguments = struct {
             if (args.flag("--zero-fill-buffers")) {
                 Bun__Node__ZeroFillBuffers = true;
             }
+
+            if (args.options("--trace-event-categories").len > 0) {
+                ctx.runtime_options.trace_event_categories = args.options("--trace-event-categories");
+            }
         }
 
         if (opts.port != null and opts.origin == null) {
@@ -1547,6 +1552,7 @@ pub const Command = struct {
         /// compatibility.
         expose_gc: bool = false,
         preserve_symlinks_main: bool = false,
+        trace_event_categories: []const []const u8 = &.{},
     };
 
     var global_cli_ctx: Context = undefined;

src/js/node/child_process.ts

@@ -735,19 +735,19 @@ 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];
+  args = [...execArgv, modulePath, ...args];
 
   if (typeof options.stdio === "string") {
     options.stdio = stdioStringToArray(options.stdio, "ipc");

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