Add trace events for Node.js environment lifecycle

simple-test.js

@@ -0,0 +1 @@
+console.log("test");

src/bun.js/VirtualMachine.zig

@@ -3,6 +3,7 @@
 //! Today, Bun is one VM per thread, so the name "VirtualMachine" sort of makes
 //! sense. If that changes, this should be renamed `ScriptExecutionContext`.
 const VirtualMachine = @This();
+const TraceEvents = @import("./trace_events.zig");
 export var has_bun_garbage_collector_flag_enabled = false;
 pub export var isBunTest: bool = false;
 
@@ -42,6 +43,8 @@ unhandled_pending_rejection_to_capture: ?*JSValue = null,
 standalone_module_graph: ?*bun.StandaloneModuleGraph = null,
 smol: bool = false,
 dns_result_order: DNSResolver.Order = .verbatim,
+trace_event_categories: ?[]const u8 = null,
+trace_events: ?*TraceEvents.TraceEvents = null,
 counters: Counters = .{},
 
 hot_reload: bun.CLI.Command.HotReload = .none,
@@ -638,6 +641,16 @@ pub fn enterUWSLoop(this: *VirtualMachine) void {
 }
 
 pub fn onBeforeExit(this: *VirtualMachine) void {
+    // Emit BeforeExit trace event
+    if (this.trace_events) |events| {
+        events.emit(.BeforeExit, "B");
+    }
+    defer {
+        if (this.trace_events) |events| {
+            events.emit(.BeforeExit, "E");
+        }
+    }
+
     this.exit_handler.dispatchOnBeforeExit();
     var dispatch = false;
     while (true) {
@@ -696,10 +709,33 @@ pub fn setEntryPointEvalResultCJS(this: *VirtualMachine, value: JSValue) callcon
 }
 
 pub fn onExit(this: *VirtualMachine) void {
+    // Emit AtExit trace event at the start
+    if (this.trace_events) |events| {
+        events.emit(.AtExit, "B");
+    }
+    defer {
+        if (this.trace_events) |events| {
+            events.emit(.AtExit, "E");
+        }
+    }
+
     this.exit_handler.dispatchOnExit();
     this.is_shutting_down = true;
 
     const rare_data = this.rare_data orelse return;
+
+    // Emit RunCleanup trace event for cleanup hooks
+    if (rare_data.cleanup_hooks.items.len > 0) {
+        if (this.trace_events) |events| {
+            events.emit(.RunCleanup, "B");
+        }
+        defer {
+            if (this.trace_events) |events| {
+                events.emit(.RunCleanup, "E");
+            }
+        }
+    }
+
     defer rare_data.cleanup_hooks.clearAndFree(bun.default_allocator);
     // Make sure we run new cleanup hooks introduced by running cleanup hooks
     while (rare_data.cleanup_hooks.items.len > 0) {
@@ -715,6 +751,11 @@ pub fn onExit(this: *VirtualMachine) void {
 extern fn Zig__GlobalObject__destructOnExit(*JSGlobalObject) void;
 
 pub fn globalExit(this: *VirtualMachine) noreturn {
+    // Close trace events if they exist
+    if (this.trace_events) |events| {
+        events.deinit();
+    }
+
     if (this.destruct_main_thread_on_exit and this.is_main_thread) {
         Zig__GlobalObject__destructOnExit(this.global);
         this.deinit();
@@ -908,6 +949,14 @@ pub fn initWithModuleGraph(
     vm.configureDebugger(opts.debugger);
     vm.body_value_hive_allocator = Body.Value.HiveAllocator.init(bun.typedAllocator(JSC.WebCore.Body.Value));
 
+    // Initialize trace events if enabled
+    TraceEvents.init(vm) catch {};
+
+    // Emit Environment trace event
+    if (vm.trace_events) |events| {
+        events.emit(.Environment, "X");
+    }
+
     return vm;
 }
 
@@ -923,6 +972,7 @@ pub const Options = struct {
     store_fd: bool = false,
     smol: bool = false,
     dns_result_order: DNSResolver.Order = .verbatim,
+    trace_event_categories: ?[]const u8 = null,
 
     // --print needs the result from evaluating the main module
     eval: bool = false,
@@ -1024,6 +1074,7 @@ pub fn init(opts: Options) !*VirtualMachine {
     uws.Loop.get().internal_loop_data.jsc_vm = vm.jsc;
     vm.smol = opts.smol;
     vm.dns_result_order = opts.dns_result_order;
+    vm.trace_event_categories = opts.trace_event_categories;
 
     if (opts.smol)
         is_smol_mode = opts.smol;
@@ -1031,6 +1082,14 @@ pub fn init(opts: Options) !*VirtualMachine {
     vm.configureDebugger(opts.debugger);
     vm.body_value_hive_allocator = Body.Value.HiveAllocator.init(bun.typedAllocator(JSC.WebCore.Body.Value));
 
+    // Initialize trace events if enabled
+    TraceEvents.init(vm) catch {};
+
+    // Emit Environment trace event
+    if (vm.trace_events) |events| {
+        events.emit(.Environment, "X");
+    }
+
     return vm;
 }
 
@@ -1188,6 +1247,17 @@ pub fn initWorker(
     vm.transpiler.setAllocator(allocator);
     vm.body_value_hive_allocator = Body.Value.HiveAllocator.init(bun.typedAllocator(JSC.WebCore.Body.Value));
 
+    // Workers should inherit trace event settings from parent
+    vm.trace_event_categories = worker.parent.trace_event_categories;
+
+    // Initialize trace events if enabled
+    TraceEvents.init(vm) catch {};
+
+    // Emit Environment trace event
+    if (vm.trace_events) |events| {
+        events.emit(.Environment, "X");
+    }
+
     return vm;
 }
 

src/bun.js/api/Timer.zig

@@ -12,6 +12,7 @@ const api = bun.api;
 const StatWatcherScheduler = @import("../node/node_fs_stat_watcher.zig").StatWatcherScheduler;
 const Timer = @This();
 const DNSResolver = @import("./bun/dns_resolver.zig").DNSResolver;
+const TraceEvents = @import("../trace_events.zig");
 
 /// TimeoutMap is map of i32 to nullable Timeout structs
 /// i32 is exposed to JavaScript and can be used with clearTimeout, clearInterval, etc.
@@ -281,6 +282,16 @@ pub const All = struct {
     }
 
     pub fn drainTimers(this: *All, vm: *VirtualMachine) void {
+        // Emit RunTimers trace event
+        if (vm.trace_events) |events| {
+            events.emit(.RunTimers, "B");
+        }
+        defer {
+            if (vm.trace_events) |events| {
+                events.emit(.RunTimers, "E");
+            }
+        }
+
         // Set in next().
         var now: timespec = undefined;
         // Split into a separate variable to avoid increasing the size of the timespec type.

src/bun.js/event_loop.zig

@@ -1,4 +1,5 @@
 const EventLoop = @This();
+const TraceEvents = @import("./trace_events.zig");
 
 tasks: Queue = undefined,
 
@@ -191,11 +192,34 @@ fn tickWithCount(this: *EventLoop, virtual_machine: *VirtualMachine) u32 {
 }
 
 pub fn tickImmediateTasks(this: *EventLoop, virtual_machine: *VirtualMachine) void {
+    // Emit CheckImmediate trace event at the start
+    if (virtual_machine.trace_events) |events| {
+        events.emit(.CheckImmediate, "B");
+    }
+    defer {
+        // Emit CheckImmediate trace event at the end
+        if (virtual_machine.trace_events) |events| {
+            events.emit(.CheckImmediate, "E");
+        }
+    }
+
     var to_run_now = this.immediate_tasks;
 
     this.immediate_tasks = this.next_immediate_tasks;
     this.next_immediate_tasks = .{};
 
+    // Emit RunAndClearNativeImmediates if we have tasks
+    if (to_run_now.items.len > 0) {
+        if (virtual_machine.trace_events) |events| {
+            events.emit(.RunAndClearNativeImmediates, "B");
+        }
+        defer {
+            if (virtual_machine.trace_events) |events| {
+                events.emit(.RunAndClearNativeImmediates, "E");
+            }
+        }
+    }
+
     var exception_thrown = false;
     for (to_run_now.items) |task| {
         exception_thrown = task.runImmediateTask(virtual_machine);

src/bun.js/trace_events.zig

@@ -0,0 +1,126 @@
+const std = @import("std");
+const bun = @import("bun");
+const JSC = bun.JSC;
+const strings = bun.strings;
+
+const TraceName = enum {
+    Environment,
+    RunAndClearNativeImmediates,
+    CheckImmediate,
+    RunTimers,
+    BeforeExit,
+    RunCleanup,
+    AtExit,
+};
+
+pub const TraceEvents = struct {
+    enabled: bool = false,
+    categories: []const u8 = "",
+    file: ?std.fs.File = null,
+    start_time: i64 = 0,
+    mutex: bun.Mutex = .{},
+    pid: std.posix.pid_t = 0,
+    first_event: bool = true,
+
+    pub fn init(vm: *JSC.VirtualMachine) !void {
+        const categories = vm.trace_event_categories orelse return;
+
+        // Check if node.environment is in the categories
+        if (!strings.contains(categories, "node.environment")) {
+            return;
+        }
+
+        var trace_events = try vm.allocator.create(TraceEvents);
+        trace_events.* = .{
+            .enabled = true,
+            .categories = categories,
+            .start_time = std.time.microTimestamp(),
+            .pid = std.posix.getpid(),
+        };
+
+        // Open trace file
+        const file = try std.fs.cwd().createFile("node_trace.1.log", .{});
+        trace_events.file = file;
+
+        // Write initial JSON array opening
+        _ = try file.writeAll("{\"traceEvents\":[\n");
+
+        // Write metadata event
+        try trace_events.writeMetadataEvent();
+
+        vm.trace_events = trace_events;
+    }
+
+    pub fn deinit(this: *TraceEvents) void {
+        if (this.file) |file| {
+            // Close JSON array
+            _ = file.writeAll("\n]}\n") catch {};
+            file.close();
+        }
+    }
+
+    fn writeMetadataEvent(this: *TraceEvents) !void {
+        if (this.file) |file| {
+            const metadata = "{\"pid\":{d},\"tid\":0,\"ts\":0,\"ph\":\"M\",\"cat\":\"__metadata\",\"name\":\"process_name\",\"args\":{{\"name\":\"bun\"}}}";
+            var buf: [256]u8 = undefined;
+            const result = try std.fmt.bufPrint(&buf, metadata, .{this.pid});
+            _ = try file.writeAll(result);
+            this.first_event = false;
+        }
+    }
+
+    pub fn emit(this: *TraceEvents, name: TraceName, phase: []const u8) void {
+        if (!this.enabled) return;
+
+        this.mutex.lock();
+        defer this.mutex.unlock();
+
+        const now = std.time.microTimestamp();
+        const ts = now - this.start_time;
+
+        this.writeEvent(name, phase, ts) catch {};
+    }
+
+    fn writeEvent(this: *TraceEvents, name: TraceName, phase: []const u8, ts: i64) !void {
+        if (this.file) |file| {
+            var buf: [512]u8 = undefined;
+
+            // Write comma if not first event
+            if (!this.first_event) {
+                _ = try file.writeAll(",\n");
+            } else {
+                this.first_event = false;
+            }
+
+            // Format the event
+            const fmt = "{{\"pid\":{d},\"tid\":0,\"ts\":{d},\"ph\":\"{s}\",\"cat\":\"node,node.environment\",\"name\":\"{s}\"}}";
+            const result = try std.fmt.bufPrint(&buf, fmt, .{
+                this.pid,
+                ts,
+                phase,
+                @tagName(name),
+            });
+
+            _ = try file.writeAll(result);
+        }
+    }
+};
+
+// Export functions to be called from other parts of the VM
+pub fn emitTraceEvent(vm: *JSC.VirtualMachine, name: TraceName) void {
+    if (vm.trace_events) |trace_events| {
+        trace_events.emit(name, "X");
+    }
+}
+
+pub fn emitTraceEventBegin(vm: *JSC.VirtualMachine, name: TraceName) void {
+    if (vm.trace_events) |trace_events| {
+        trace_events.emit(name, "B");
+    }
+}
+
+pub fn emitTraceEventEnd(vm: *JSC.VirtualMachine, name: TraceName) void {
+    if (vm.trace_events) |trace_events| {
+        trace_events.emit(name, "E");
+    }
+}

src/bun_js.zig

@@ -192,6 +192,7 @@ pub const Run = struct {
                     .eval = ctx.runtime_options.eval.eval_and_print,
                     .debugger = ctx.runtime_options.debugger,
                     .dns_result_order = DNSResolver.Order.fromStringOrDie(ctx.runtime_options.dns_result_order),
+                    .trace_event_categories = ctx.runtime_options.trace_event_categories,
                     .is_main_thread = true,
                     .destruct_main_thread_on_exit = bun.getRuntimeFeatureFlag(.BUN_DESTRUCT_VM_ON_EXIT),
                 },

src/cli.zig

@@ -231,6 +231,7 @@ pub const Arguments = struct {
         clap.parseParam("--max-http-header-size <INT>      Set the maximum size of HTTP headers in bytes. Default is 16KiB") catch unreachable,
         clap.parseParam("--dns-result-order <STR>          Set the default order of DNS lookup results. Valid orders: verbatim (default), ipv4first, ipv6first") catch unreachable,
         clap.parseParam("--expose-gc                       Expose gc() on the global object. Has no effect on Bun.gc().") catch unreachable,
+        clap.parseParam("--trace-event-categories <STR>    Enable trace events for the specified categories (comma-separated). Use 'node.environment' for Node.js environment events.") catch unreachable,
         clap.parseParam("--no-deprecation                  Suppress all reporting of the custom deprecation.") catch unreachable,
         clap.parseParam("--throw-deprecation               Determine whether or not deprecation warnings result in errors.") catch unreachable,
         clap.parseParam("--title <STR>                     Set the process title") catch unreachable,
@@ -798,6 +799,10 @@ pub const Arguments = struct {
             ctx.runtime_options.preconnect = args.options("--fetch-preconnect");
             ctx.runtime_options.expose_gc = args.flag("--expose-gc");
 
+            if (args.option("--trace-event-categories")) |categories| {
+                ctx.runtime_options.trace_event_categories = categories;
+            }
+
             if (args.option("--dns-result-order")) |order| {
                 ctx.runtime_options.dns_result_order = order;
             }
@@ -1546,6 +1551,8 @@ pub const Command = struct {
         /// `--expose-gc` makes `globalThis.gc()` available. Added for Node
         /// compatibility.
         expose_gc: bool = false,
+        /// Trace event categories to enable
+        trace_event_categories: ?[]const u8 = null,
         preserve_symlinks_main: bool = false,
     };
 

src/js/node/child_process.ts

@@ -735,19 +735,22 @@ function fork(modulePath, args = [], options) {
   validateArgumentNullCheck(options.execPath, "options.execPath");
 
   // Prepare arguments for fork:
-  // execArgv = options.execArgv || process.execArgv;
-  // validateArgumentsNullCheck(execArgv, "options.execArgv");
+  const 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);
-  //   }
-  // }
-
-  args = [/*...execArgv,*/ modulePath, ...args];
+  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.
+      const newExecArgv = ArrayPrototypeSlice.$call(execArgv);
+      ArrayPrototypeSplice.$call(newExecArgv, index - 1, 2);
+      args = [...newExecArgv, modulePath, ...args];
+    } else {
+      args = [...execArgv, modulePath, ...args];
+    }
+  } else {
+    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);
+  }));
+}