Add trace events support for Node.js-compatible performance tracing

.gitignore

@@ -183,4 +183,4 @@ codegen-for-zig-team.tar.gz
 *.sock
 scratch*.{js,ts,tsx,cjs,mjs}
 
-*.bun-build
+*.bun-build/bun/

src/bun.js/VirtualMachine.zig

@@ -638,6 +638,10 @@ pub fn enterUWSLoop(this: *VirtualMachine) void {
 }
 
 pub fn onBeforeExit(this: *VirtualMachine) void {
+    // Emit BeforeExit trace event
+    const timer = trace_events.TraceTimer.begin("BeforeExit", "node.environment");
+    defer timer.end();
+
     this.exit_handler.dispatchOnBeforeExit();
     var dispatch = false;
     while (true) {
@@ -696,11 +700,20 @@ pub fn setEntryPointEvalResultCJS(this: *VirtualMachine, value: JSValue) callcon
 }
 
 pub fn onExit(this: *VirtualMachine) void {
+    // Emit AtExit trace event
+    const timer = trace_events.TraceTimer.begin("AtExit", "node.environment");
+    defer timer.end();
+
     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);
+
+    // Emit RunCleanup trace event
+    trace_events.emit("RunCleanup", "node.environment", .Begin);
+    defer trace_events.emit("RunCleanup", "node.environment", .End);
+
     // 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;
@@ -719,6 +732,10 @@ pub fn globalExit(this: *VirtualMachine) noreturn {
         Zig__GlobalObject__destructOnExit(this.global);
         this.deinit();
     }
+
+    // Finalize trace events before exit
+    trace_events.deinit();
+
     bun.Global.exit(this.exit_handler.exit_code);
 }
 
@@ -3566,3 +3583,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

@@ -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 trace_events = @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,10 @@ pub const All = struct {
     }
 
     pub fn drainTimers(this: *All, vm: *VirtualMachine) void {
+        // Emit RunTimers trace event
+        const timer = trace_events.TraceTimer.begin("RunTimers", "node.environment");
+        defer timer.end();
+
         // 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

@@ -1,4 +1,5 @@
 const EventLoop = @This();
+const trace_events = @import("../trace_events.zig");
 
 tasks: Queue = undefined,
 
@@ -191,11 +192,19 @@ fn tickWithCount(this: *EventLoop, virtual_machine: *VirtualMachine) u32 {
 }
 
 pub fn tickImmediateTasks(this: *EventLoop, virtual_machine: *VirtualMachine) void {
+    // Emit CheckImmediate trace event
+    const timer = trace_events.TraceTimer.begin("CheckImmediate", "node.environment");
+    defer timer.end();
+
     var to_run_now = this.immediate_tasks;
 
     this.immediate_tasks = this.next_immediate_tasks;
     this.next_immediate_tasks = .{};
 
+    // Emit RunAndClearNativeImmediates trace event
+    trace_events.emit("RunAndClearNativeImmediates", "node.environment", .Begin);
+    defer trace_events.emit("RunAndClearNativeImmediates", "node.environment", .End);
+
     var exception_thrown = false;
     for (to_run_now.items) |task| {
         exception_thrown = task.runImmediateTask(virtual_machine);

src/bun.zig

@@ -154,6 +154,7 @@ pub const PackageJSON = @import("./resolver/package_json.zig").PackageJSON;
 pub const fmt = @import("./fmt.zig");
 pub const allocators = @import("./allocators.zig");
 pub const bun_js = @import("./bun_js.zig");
+pub const trace_events = @import("./trace_events.zig");
 
 // This file is gennerated, but cant be placed in the build/debug/codegen
 // folder because zig will complain about outside-of-module stuff

src/bun_js.zig

@@ -18,6 +18,7 @@ const JSC = bun.JSC;
 const AsyncHTTP = bun.http.AsyncHTTP;
 const Arena = @import("./allocators/mimalloc_arena.zig").Arena;
 const DNSResolver = @import("bun.js/api/bun/dns_resolver.zig").DNSResolver;
+const trace_events = @import("./trace_events.zig");
 
 const OpaqueWrap = JSC.OpaqueWrap;
 const VirtualMachine = JSC.VirtualMachine;
@@ -114,6 +115,14 @@ pub const Run = struct {
 
         doPreconnect(ctx.runtime_options.preconnect);
 
+        // Initialize trace events if requested
+        if (ctx.runtime_options.trace_event_categories.len > 0) {
+            trace_events.init(vm.allocator, ctx.runtime_options.trace_event_categories) catch |err| {
+                Output.prettyErrorln("Failed to initialize trace events: {s}", .{@errorName(err)});
+                Global.exit(1);
+            };
+        }
+
         const callback = OpaqueWrap(Run, Run.start);
         vm.global.vm().holdAPILock(&run, callback);
     }
@@ -268,6 +277,14 @@ pub const Run = struct {
 
         doPreconnect(ctx.runtime_options.preconnect);
 
+        // Initialize trace events if requested
+        if (ctx.runtime_options.trace_event_categories.len > 0) {
+            trace_events.init(vm.allocator, ctx.runtime_options.trace_event_categories) catch |err| {
+                Output.prettyErrorln("Failed to initialize trace events: {s}", .{@errorName(err)});
+                Global.exit(1);
+            };
+        }
+
         vm.main_is_html_entrypoint = (loader orelse vm.transpiler.options.loader(std.fs.path.extension(entry_path))) == .html;
 
         const callback = OpaqueWrap(Run, Run.start);
@@ -284,6 +301,9 @@ pub const Run = struct {
         vm.hot_reload = this.ctx.debug.hot_reload;
         vm.onUnhandledRejection = &onUnhandledRejectionBeforeClose;
 
+        // Emit Environment trace event
+        trace_events.emit("Environment", "node.environment", .Instant);
+
         this.addConditionalGlobals();
         do_redis_preconnect: {
             // This must happen within the API lock, which is why it's not in the "doPreconnect" function

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 specified categories (e.g. node.environment)") 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;

src/trace_events.zig

@@ -0,0 +1,228 @@
+const std = @import("std");
+const bun = @import("bun");
+const Output = bun.Output;
+const JSC = bun.JSC;
+
+pub const TraceEventPhase = enum(u8) {
+    Begin = 'B',
+    End = 'E',
+    Complete = 'X',
+    Instant = 'I',
+    AsyncBegin = 'b',
+    AsyncEnd = 'e',
+    Metadata = 'M',
+};
+
+pub const TraceEvent = struct {
+    name: []const u8,
+    cat: []const u8,
+    ph: TraceEventPhase,
+    pid: i32,
+    tid: i32,
+    ts: i64,
+    dur: ?i64 = null,
+    args: ?std.json.Value = null,
+};
+
+pub const TraceEventCollector = struct {
+    events: std.ArrayList(TraceEvent),
+    allocator: std.mem.Allocator,
+    enabled_categories: []const u8,
+    process_id: i32,
+    thread_id: i32,
+    file_handle: ?std.fs.File = null,
+    mutex: std.Thread.Mutex = .{},
+
+    const Self = @This();
+
+    pub fn init(allocator: std.mem.Allocator, categories: []const u8) !*Self {
+        var self = try allocator.create(Self);
+        self.* = .{
+            .events = std.ArrayList(TraceEvent).init(allocator),
+            .allocator = allocator,
+            .enabled_categories = categories,
+            .process_id = std.c.getpid(),
+            .thread_id = @intCast(std.c.gettid()),
+        };
+
+        // Open the trace file
+        if (categories.len > 0) {
+            self.file_handle = try std.fs.cwd().createFile("node_trace.1.log", .{ .truncate = true });
+
+            // Write the initial metadata event
+            try self.writeHeader();
+        }
+
+        return self;
+    }
+
+    pub fn deinit(self: *Self) void {
+        if (self.file_handle) |file| {
+            self.writeFooter() catch {};
+            file.close();
+        }
+        self.events.deinit();
+        self.allocator.destroy(self);
+    }
+
+    fn writeHeader(self: *Self) !void {
+        if (self.file_handle) |file| {
+            try file.writeAll("{\"traceEvents\":[\n");
+
+            // Write metadata event
+            const metadata = TraceEvent{
+                .name = "process_name",
+                .cat = "__metadata",
+                .ph = .Metadata,
+                .pid = self.process_id,
+                .tid = self.thread_id,
+                .ts = 0,
+                .args = std.json.Value{ .object = std.json.ObjectMap.init(self.allocator) },
+            };
+
+            try self.writeEvent(file, metadata, false);
+        }
+    }
+
+    fn writeFooter(self: *Self) !void {
+        if (self.file_handle) |file| {
+            try file.writeAll("\n]}");
+        }
+    }
+
+    fn writeEvent(_: *Self, file: std.fs.File, event: TraceEvent, needs_comma: bool) !void {
+        if (needs_comma) {
+            try file.writeAll(",\n");
+        }
+
+        try file.writeAll("{");
+        try std.fmt.format(file.writer(), "\"name\":\"{s}\",\"cat\":\"{s}\",\"ph\":\"{c}\",\"pid\":{d},\"tid\":{d},\"ts\":{d}", .{
+            event.name,
+            event.cat,
+            @intFromEnum(event.ph),
+            event.pid,
+            event.tid,
+            event.ts,
+        });
+
+        if (event.dur) |dur| {
+            try std.fmt.format(file.writer(), ",\"dur\":{d}", .{dur});
+        }
+
+        if (event.args) |args| {
+            try file.writeAll(",\"args\":");
+            try std.json.stringify(args, .{}, file.writer());
+        }
+
+        try file.writeAll("}");
+    }
+
+    pub fn emit(self: *Self, name: []const u8, category: []const u8, phase: TraceEventPhase) !void {
+        if (!self.isEnabled(category)) return;
+
+        self.mutex.lock();
+        defer self.mutex.unlock();
+
+        const now = std.time.microTimestamp();
+        const event = TraceEvent{
+            .name = name,
+            .cat = category,
+            .ph = phase,
+            .pid = self.process_id,
+            .tid = @intCast(std.c.gettid()),
+            .ts = now,
+        };
+
+        if (self.file_handle) |file| {
+            try self.writeEvent(file, event, self.events.items.len > 0);
+        }
+
+        try self.events.append(event);
+    }
+
+    pub fn emitComplete(self: *Self, name: []const u8, category: []const u8, duration_us: i64) !void {
+        if (!self.isEnabled(category)) return;
+
+        self.mutex.lock();
+        defer self.mutex.unlock();
+
+        const now = std.time.microTimestamp();
+        const event = TraceEvent{
+            .name = name,
+            .cat = category,
+            .ph = .Complete,
+            .pid = self.process_id,
+            .tid = @intCast(std.c.gettid()),
+            .ts = now - duration_us,
+            .dur = duration_us,
+        };
+
+        if (self.file_handle) |file| {
+            try self.writeEvent(file, event, self.events.items.len > 0);
+        }
+
+        try self.events.append(event);
+    }
+
+    fn isEnabled(self: *Self, category: []const u8) bool {
+        if (self.enabled_categories.len == 0) return false;
+
+        // Check if the category is in the enabled list
+        var it = std.mem.tokenize(u8, self.enabled_categories, ",");
+        while (it.next()) |enabled_cat| {
+            if (std.mem.eql(u8, enabled_cat, category)) {
+                return true;
+            }
+        }
+
+        return false;
+    }
+};
+
+var global_trace_collector: ?*TraceEventCollector = null;
+
+pub fn init(allocator: std.mem.Allocator, categories: []const u8) !void {
+    if (categories.len == 0) return;
+
+    global_trace_collector = try TraceEventCollector.init(allocator, categories);
+}
+
+pub fn deinit() void {
+    if (global_trace_collector) |collector| {
+        collector.deinit();
+        global_trace_collector = null;
+    }
+}
+
+pub fn emit(name: []const u8, category: []const u8, phase: TraceEventPhase) void {
+    if (global_trace_collector) |collector| {
+        collector.emit(name, category, phase) catch {};
+    }
+}
+
+pub fn emitComplete(name: []const u8, category: []const u8, duration_us: i64) void {
+    if (global_trace_collector) |collector| {
+        collector.emitComplete(name, category, duration_us) catch {};
+    }
+}
+
+// Helper struct for measuring duration
+pub const TraceTimer = struct {
+    name: []const u8,
+    category: []const u8,
+    start_time: i64,
+
+    pub fn begin(name: []const u8, category: []const u8) TraceTimer {
+        emit(name, category, .Begin);
+        return .{
+            .name = name,
+            .category = category,
+            .start_time = std.time.microTimestamp(),
+        };
+    }
+
+    pub fn end(self: TraceTimer) void {
+        const duration = std.time.microTimestamp() - self.start_time;
+        emitComplete(self.name, self.category, duration);
+    }
+};

src/trace_events_implementation.md

@@ -0,0 +1,83 @@
+# Node.js Trace Events Implementation in Bun
+
+This document describes the implementation of Node.js-compatible trace events in Bun.
+
+## Overview
+
+The trace events feature allows Bun to emit performance and diagnostic events in the Chrome Trace Event Format, compatible with Node.js's `--trace-event-categories` flag.
+
+## Implementation Details
+
+### Files Modified
+
+1. **src/trace_events.zig** - Core trace events module
+
+   - Implements the trace event collector
+   - Handles writing events to `node_trace.1.log` in JSON format
+   - Supports filtering by categories
+
+2. **src/cli.zig** - Command-line interface
+
+   - Added `--trace-event-categories <STR>` parameter
+   - Added `trace_event_categories` field to `RuntimeOptions`
+   - Parses the flag and stores the categories
+
+3. **src/bun_js.zig** - Runtime initialization
+
+   - Initializes trace events if categories are specified
+   - Emits "Environment" event on startup
+
+4. **src/bun.js/event_loop.zig** - Event loop integration
+
+   - Emits "CheckImmediate" event when checking immediate tasks
+   - Emits "RunAndClearNativeImmediates" event when running immediate tasks
+
+5. **src/bun.js/api/Timer.zig** - Timer events
+
+   - Emits "RunTimers" event when draining timers
+
+6. **src/bun.js/VirtualMachine.zig** - VM lifecycle events
+   - Emits "BeforeExit" event in `onBeforeExit()`
+   - Emits "AtExit" event in `onExit()`
+   - Emits "RunCleanup" event during cleanup hook execution
+   - Calls `trace_events.deinit()` to flush events before exit
+
+## Trace Event Categories
+
+Currently supports the "node.environment" category which includes:
+
+- **Environment** - Emitted when the VM starts
+- **CheckImmediate** - Emitted when checking for immediate tasks
+- **RunAndClearNativeImmediates** - Emitted when running immediate tasks
+- **RunTimers** - Emitted when running timers
+- **BeforeExit** - Emitted before the process exits
+- **RunCleanup** - Emitted during cleanup hook execution
+- **AtExit** - Emitted at process exit
+
+## Output Format
+
+Events are written to `node_trace.1.log` in the Chrome Trace Event Format:
+
+```json
+{
+  "traceEvents": [
+    {
+      "name": "Environment",
+      "cat": "node.environment",
+      "ph": "I",
+      "pid": 12345,
+      "tid": 12345,
+      "ts": 1234567890
+    },
+    ...
+  ]
+}
+```
+
+## Usage
+
+```bash
+bun --trace-event-categories node.environment script.js
+```
+
+This will generate a `node_trace.1.log` file in the current working directory containing the trace events.

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