Add Node.js trace events support with CLI flag and lifecycle hooks

cmake/sources/CxxSources.txt

@@ -160,6 +160,7 @@ src/bun.js/bindings/NodeFSStatFSBinding.cpp
 src/bun.js/bindings/NodeHTTP.cpp
 src/bun.js/bindings/NodeTimerObject.cpp
 src/bun.js/bindings/NodeTLS.cpp
+src/bun.js/bindings/NodeTraceEvents.cpp
 src/bun.js/bindings/NodeURL.cpp
 src/bun.js/bindings/NodeValidator.cpp
 src/bun.js/bindings/NodeVM.cpp

src/bun.js/VirtualMachine.zig

@@ -638,6 +638,8 @@ pub fn enterUWSLoop(this: *VirtualMachine) void {
 }
 
 pub fn onBeforeExit(this: *VirtualMachine) void {
+    trace_events.NodeTraceEvents.emitBeforeExit();
+
     this.exit_handler.dispatchOnBeforeExit();
     var dispatch = false;
     while (true) {
@@ -696,6 +698,8 @@ pub fn setEntryPointEvalResultCJS(this: *VirtualMachine, value: JSValue) callcon
 }
 
 pub fn onExit(this: *VirtualMachine) void {
+    trace_events.NodeTraceEvents.emitAtExit();
+
     this.exit_handler.dispatchOnExit();
     this.is_shutting_down = true;
 
@@ -3566,3 +3570,11 @@ const DotEnv = bun.DotEnv;
 const HotReloader = JSC.hot_reloader.HotReloader;
 const Body = webcore.Body;
 const Counters = @import("./Counters.zig");
+const EventLoopHandle = JSC.EventLoopHandle;
+const PackageJSON = options.PackageJSON;
+const MacroMap = @import("./api/JSBundler.zig").MacroMap;
+const timestamp = @import("./bun.js/bindings/shimmer.zig").shimmer().millitime;
+const simdutf = bun.simdutf;
+const trace_events = @import("./trace_events.zig");
+
+pub const has_created_instance_map: std.EnumArray(InitializedFramework, bool) = std.EnumArray(InitializedFramework, bool).initDefault(false, .{});

src/bun.js/bindings/NodeTraceEvents.cpp

@@ -0,0 +1,191 @@
+#include "root.h"
+#include "NodeTraceEvents.h"
+#include <JavaScriptCore/JSGlobalObject.h>
+#include <JavaScriptCore/JSONObject.h>
+#include <filesystem>
+#include <fstream>
+#include <chrono>
+#include <unistd.h>
+#include <pthread.h>
+#include <sstream>
+#include <iomanip>
+#include <JavaScriptCore/JSFunction.h>
+#include <JavaScriptCore/JSCInlines.h>
+#include "ZigGlobalObject.h"
+
+namespace Bun {
+
+static std::unique_ptr<NodeTraceEvents> s_instance;
+static std::mutex s_mutex;
+
+NodeTraceEvents& NodeTraceEvents::getInstance()
+{
+    std::lock_guard<std::mutex> lock(s_mutex);
+    if (!s_instance) {
+        s_instance = std::unique_ptr<NodeTraceEvents>(new NodeTraceEvents());
+    }
+    return *s_instance;
+}
+
+void NodeTraceEvents::enable(const WTF::String& categories)
+{
+    std::lock_guard<std::mutex> lock(m_mutex);
+    m_enabled = true;
+    m_categories = categories;
+    
+    // Create trace file with rotation number
+    m_filename = WTF::String::format("node_trace.%d.log", m_rotation);
+    
+    // Initialize with empty trace events array
+    m_events.clear();
+    
+    // Reset start time
+    m_startTime = std::chrono::steady_clock::now();
+}
+
+void NodeTraceEvents::disable()
+{
+    std::lock_guard<std::mutex> lock(m_mutex);
+    if (!m_enabled)
+        return;
+        
+    m_enabled = false;
+    writeTraceFile();
+    m_events.clear();
+}
+
+void NodeTraceEvents::emitEvent(const WTF::String& name, const WTF::String& category, const char phase)
+{
+    if (!m_enabled)
+        return;
+        
+    std::lock_guard<std::mutex> lock(m_mutex);
+    
+    auto now = std::chrono::steady_clock::now();
+    auto duration = std::chrono::duration_cast<std::chrono::microseconds>(now - m_startTime);
+    
+    TraceEvent event;
+    event.name = name;
+    event.cat = category;
+    event.ph = WTF::String(&phase, 1);
+    event.pid = getpid();
+    event.tid = static_cast<long>(pthread_self());
+    event.ts = duration.count();
+    
+    m_events.append(WTFMove(event));
+}
+
+void NodeTraceEvents::writeTraceFile()
+{
+    if (m_events.isEmpty())
+        return;
+        
+    std::ostringstream json;
+    json << "{\"traceEvents\":[";
+    
+    bool first = true;
+    for (const auto& event : m_events) {
+        if (!first) {
+            json << ",";
+        }
+        first = false;
+        
+        json << "{";
+        json << "\"name\":\"" << event.name.utf8().data() << "\",";
+        json << "\"cat\":\"" << event.cat.utf8().data() << "\",";
+        json << "\"ph\":\"" << event.ph.utf8().data() << "\",";
+        json << "\"pid\":" << event.pid << ",";
+        json << "\"tid\":" << event.tid << ",";
+        json << "\"ts\":" << event.ts;
+        json << "}";
+    }
+    
+    json << "]}";
+    
+    // Write to file
+    std::ofstream file(m_filename.utf8().data());
+    if (file.is_open()) {
+        file << json.str();
+        file.close();
+    }
+}
+
+JSC::JSValue createNodeTraceEventsBindings(Zig::GlobalObject* globalObject)
+{
+    auto& vm = globalObject->vm();
+    auto* obj = JSC::constructEmptyObject(globalObject);
+    
+    obj->putDirect(vm, JSC::Identifier::fromString(vm, "enableTraceEvents"_s),
+        JSC::JSFunction::create(vm, globalObject, 1, "enableTraceEvents"_s, 
+            [](JSC::JSGlobalObject* globalObject, JSC::CallFrame* callFrame) -> JSC::EncodedJSValue {
+                auto& vm = globalObject->vm();
+                auto scope = DECLARE_THROW_SCOPE(vm);
+                
+                if (callFrame->argumentCount() < 1) {
+                    return JSC::JSValue::encode(JSC::jsUndefined());
+                }
+                
+                auto categories = callFrame->argument(0).toWTFString(globalObject);
+                RETURN_IF_EXCEPTION(scope, {});
+                
+                Bun__enableTraceEvents(categories.utf8().data());
+                return JSC::JSValue::encode(JSC::jsUndefined());
+            }));
+    
+    obj->putDirect(vm, JSC::Identifier::fromString(vm, "disableTraceEvents"_s),
+        JSC::JSFunction::create(vm, globalObject, 0, "disableTraceEvents"_s,
+            [](JSC::JSGlobalObject*, JSC::CallFrame*) -> JSC::EncodedJSValue {
+                Bun__disableTraceEvents();
+                return JSC::JSValue::encode(JSC::jsUndefined());
+            }));
+    
+    obj->putDirect(vm, JSC::Identifier::fromString(vm, "emitTraceEvent"_s),
+        JSC::JSFunction::create(vm, globalObject, 2, "emitTraceEvent"_s,
+            [](JSC::JSGlobalObject* globalObject, JSC::CallFrame* callFrame) -> JSC::EncodedJSValue {
+                auto& vm = globalObject->vm();
+                auto scope = DECLARE_THROW_SCOPE(vm);
+                
+                if (callFrame->argumentCount() < 2) {
+                    return JSC::JSValue::encode(JSC::jsUndefined());
+                }
+                
+                auto name = callFrame->argument(0).toWTFString(globalObject);
+                RETURN_IF_EXCEPTION(scope, {});
+                
+                auto category = callFrame->argument(1).toWTFString(globalObject);
+                RETURN_IF_EXCEPTION(scope, {});
+                
+                Bun__emitTraceEvent(name.utf8().data(), category.utf8().data());
+                return JSC::JSValue::encode(JSC::jsUndefined());
+            }));
+    
+    return obj;
+}
+
+} // namespace Bun
+
+extern "C" {
+
+void Bun__enableTraceEvents(const char* categories)
+{
+    if (categories && strlen(categories) > 0) {
+        Bun::NodeTraceEvents::getInstance().enable(WTF::String::fromUTF8(categories));
+    }
+}
+
+void Bun__disableTraceEvents()
+{
+    Bun::NodeTraceEvents::getInstance().disable();
+}
+
+void Bun__emitTraceEvent(const char* name, const char* category)
+{
+    if (name && category) {
+        Bun::NodeTraceEvents::getInstance().emitEvent(
+            WTF::String::fromUTF8(name),
+            WTF::String::fromUTF8(category)
+        );
+    }
+}
+
+} // extern "C"

src/bun.js/bindings/NodeTraceEvents.h

@@ -0,0 +1,55 @@
+#pragma once
+
+#include <wtf/text/WTFString.h>
+#include <wtf/Vector.h>
+#include <mutex>
+#include <chrono>
+#include <memory>
+
+namespace JSC {
+class JSGlobalObject;
+}
+
+namespace Bun {
+
+class NodeTraceEvents {
+public:
+    static NodeTraceEvents& getInstance();
+    
+    void enable(const WTF::String& categories);
+    void disable();
+    void emitEvent(const WTF::String& name, const WTF::String& category, const char phase = 'I');
+    bool isEnabled() const { return m_enabled; }
+    
+private:
+    NodeTraceEvents() : m_startTime(std::chrono::steady_clock::now()), m_rotation(1) {}
+    
+    struct TraceEvent {
+        WTF::String name;
+        WTF::String cat;
+        WTF::String ph; // phase
+        int pid;
+        long tid;
+        uint64_t ts; // timestamp in microseconds
+        // args can be added later if needed
+    };
+    
+    void writeTraceFile();
+    
+    bool m_enabled = false;
+    WTF::String m_categories;
+    WTF::String m_filename;
+    WTF::Vector<TraceEvent> m_events;
+    std::chrono::steady_clock::time_point m_startTime;
+    std::mutex m_mutex;
+    int m_rotation;
+};
+
+} // namespace Bun
+
+// C interface for Zig
+extern "C" {
+void Bun__enableTraceEvents(const char* categories);
+void Bun__disableTraceEvents();
+void Bun__emitTraceEvent(const char* name, const char* category);
+}

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,5 +1,7 @@
 const EventLoop = @This();
 
+const trace_events = @import("./trace_events.zig");
+
 tasks: Queue = undefined,
 
 /// setImmediate() gets it's own two task queues
@@ -191,6 +193,8 @@ fn tickWithCount(this: *EventLoop, virtual_machine: *VirtualMachine) u32 {
 }
 
 pub fn tickImmediateTasks(this: *EventLoop, virtual_machine: *VirtualMachine) void {
+    trace_events.NodeTraceEvents.emitCheckImmediate();
+
     var to_run_now = this.immediate_tasks;
 
     this.immediate_tasks = this.next_immediate_tasks;
@@ -364,6 +368,7 @@ pub fn autoTick(this: *EventLoop) void {
 
     if (Environment.isPosix) {
         ctx.timer.drainTimers(ctx);
+        trace_events.NodeTraceEvents.emitRunTimers();
     }
 
     ctx.onAfterEventLoop();
@@ -433,6 +438,7 @@ pub fn autoTickActive(this: *EventLoop) void {
 
     if (Environment.isPosix) {
         ctx.timer.drainTimers(ctx);
+        trace_events.NodeTraceEvents.emitRunTimers();
     }
 
     ctx.onAfterEventLoop();
@@ -644,3 +650,9 @@ const Environment = bun.Environment;
 const Waker = bun.Async.Waker;
 const uws = bun.uws;
 const Async = bun.Async;
+
+pub fn drainTimers(all: *Timer.All, vm: *VirtualMachine) void {
+    trace_events.NodeTraceEvents.emitRunTimers();
+
+    Timer.drainTimers(all, vm);
+}

src/bun.js/trace_events.zig

@@ -0,0 +1,90 @@
+const std = @import("std");
+const bun = @import("root").bun;
+const JSC = bun.JSC;
+
+// External C functions from NodeTraceEvents.cpp
+extern "C" fn Bun__enableTraceEvents(categories: [*:0]const u8) void;
+extern "C" fn Bun__disableTraceEvents() void;
+extern "C" fn Bun__emitTraceEvent(name: [*:0]const u8, category: [*:0]const u8) void;
+
+pub const NodeTraceEvents = struct {
+    var enabled: bool = false;
+    var categories: []const u8 = "";
+
+    pub fn init() void {
+        // Check if trace events were enabled via CLI
+        if (bun.getenvZ("NODE_TRACE_EVENT_CATEGORIES")) |cats| {
+            enable(cats);
+
+            // Emit initial environment event
+            emitEvent("Environment", "node.environment");
+        }
+    }
+
+    pub fn enable(cats: []const u8) void {
+        if (enabled) return;
+
+        enabled = true;
+        categories = cats;
+
+        // Add null terminator for C function
+        var buf: [4096]u8 = undefined;
+        const len = @min(cats.len, buf.len - 1);
+        @memcpy(buf[0..len], cats[0..len]);
+        buf[len] = 0;
+
+        Bun__enableTraceEvents(&buf);
+    }
+
+    pub fn disable() void {
+        if (!enabled) return;
+
+        enabled = false;
+        Bun__disableTraceEvents();
+    }
+
+    pub fn emitEvent(name: []const u8, category: []const u8) void {
+        if (!enabled) return;
+
+        // Add null terminators for C functions
+        var name_buf: [256]u8 = undefined;
+        var cat_buf: [256]u8 = undefined;
+
+        const name_len = @min(name.len, name_buf.len - 1);
+        @memcpy(name_buf[0..name_len], name[0..name_len]);
+        name_buf[name_len] = 0;
+
+        const cat_len = @min(category.len, cat_buf.len - 1);
+        @memcpy(cat_buf[0..cat_len], category[0..cat_len]);
+        cat_buf[cat_len] = 0;
+
+        Bun__emitTraceEvent(&name_buf, &cat_buf);
+    }
+
+    // Lifecycle event emitters
+    pub fn emitRunAndClearNativeImmediates() void {
+        emitEvent("RunAndClearNativeImmediates", "node.environment");
+    }
+
+    pub fn emitCheckImmediate() void {
+        emitEvent("CheckImmediate", "node.environment");
+    }
+
+    pub fn emitRunTimers() void {
+        emitEvent("RunTimers", "node.environment");
+    }
+
+    pub fn emitBeforeExit() void {
+        emitEvent("BeforeExit", "node.environment");
+    }
+
+    pub fn emitRunCleanup() void {
+        emitEvent("RunCleanup", "node.environment");
+    }
+
+    pub fn emitAtExit() void {
+        emitEvent("AtExit", "node.environment");
+        // Disable trace events at exit to ensure file is written
+        disable();
+    }
+};

src/bun_js.zig

@@ -18,6 +18,8 @@ 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 io = std.io;
+const trace_events = @import("./bun.js/trace_events.zig");
 
 const OpaqueWrap = JSC.OpaqueWrap;
 const VirtualMachine = JSC.VirtualMachine;
@@ -112,6 +114,12 @@ pub const Run = struct {
         vm.is_main_thread = true;
         JSC.VirtualMachine.is_main_thread_vm = true;
 
+        // Initialize trace events if enabled via CLI
+        if (ctx.runtime_options.trace_event_categories.len > 0) {
+            b.env.map.put("NODE_TRACE_EVENT_CATEGORIES", ctx.runtime_options.trace_event_categories) catch {};
+        }
+        trace_events.NodeTraceEvents.init();
+
         doPreconnect(ctx.runtime_options.preconnect);
 
         const callback = OpaqueWrap(Run, Run.start);
@@ -257,6 +265,12 @@ pub const Run = struct {
         vm.is_main_thread = true;
         JSC.VirtualMachine.is_main_thread_vm = true;
 
+        // Initialize trace events if enabled via CLI
+        if (ctx.runtime_options.trace_event_categories.len > 0) {
+            b.env.map.put("NODE_TRACE_EVENT_CATEGORIES", ctx.runtime_options.trace_event_categories) catch {};
+        }
+        trace_events.NodeTraceEvents.init();
+
         // Allow setting a custom timezone
         if (vm.transpiler.env.get("TZ")) |tz| {
             if (tz.len > 0) {

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 capture for the specified categories") catch unreachable,
     };
 
     const auto_or_run_params = [_]ParamType{
@@ -706,6 +707,10 @@ pub const Arguments = struct {
                 ctx.runtime_options.redis_preconnect = true;
             }
 
+            if (args.option("--trace-event-categories")) |categories| {
+                ctx.runtime_options.trace_event_categories = categories;
+            }
+
             if (args.flag("--no-addons")) {
                 // used for disabling process.dlopen and
                 // for disabling export condition "node-addons"
@@ -1547,6 +1552,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/cli/test_command.zig

@@ -1016,12 +1016,25 @@ pub const TestCommand = struct {
         Output.prettyln("<r><b>bun test <r><d>v" ++ Global.package_json_version_with_sha ++ "<r>", .{});
         Output.flush();
 
-        var env_loader = brk: {
+        var loader = brk: {
             const map = try ctx.allocator.create(DotEnv.Map);
             map.* = DotEnv.Map.init(ctx.allocator);
 
             const loader = try ctx.allocator.create(DotEnv.Loader);
             loader.* = DotEnv.Loader.init(map, ctx.allocator);
+
+            // Set NODE_TRACE_EVENT_CATEGORIES if specified via CLI
+            if (ctx.runtime_options.trace_event_categories.len > 0) {
+                const entry = try loader.map.getOrPutWithoutValue("NODE_TRACE_EVENT_CATEGORIES");
+                if (!entry.found_existing) {
+                    entry.key_ptr.* = try loader.allocator.dupe(u8, entry.key_ptr.*);
+                }
+                entry.value_ptr.* = .{
+                    .value = try loader.allocator.dupe(u8, ctx.runtime_options.trace_event_categories),
+                    .conditional = false,
+                };
+            }
+
             break :brk loader;
         };
         bun.JSC.initialize(false);
@@ -1082,7 +1095,7 @@ pub const TestCommand = struct {
                 .allocator = ctx.allocator,
                 .args = ctx.args,
                 .log = ctx.log,
-                .env_loader = env_loader,
+                .env_loader = loader,
                 // we must store file descriptors because we reuse them for
                 // iterating through the directory tree recursively
                 //
@@ -1100,11 +1113,11 @@ pub const TestCommand = struct {
         vm.transpiler.options.rewrite_jest_for_tests = true;
         vm.transpiler.options.env.behavior = .load_all_without_inlining;
 
-        const node_env_entry = try env_loader.map.getOrPutWithoutValue("NODE_ENV");
+        const node_env_entry = try loader.map.getOrPutWithoutValue("NODE_ENV");
         if (!node_env_entry.found_existing) {
-            node_env_entry.key_ptr.* = try env_loader.allocator.dupe(u8, node_env_entry.key_ptr.*);
+            node_env_entry.key_ptr.* = try loader.allocator.dupe(u8, node_env_entry.key_ptr.*);
             node_env_entry.value_ptr.* = .{
-                .value = try env_loader.allocator.dupe(u8, "test"),
+                .value = try loader.allocator.dupe(u8, "test"),
                 .conditional = false,
             };
         }

src/js/node/trace_events.ts

@@ -1,23 +1,70 @@
 // Hardcoded module "node:trace_events"
-// This is a stub! This is not actually implemented yet.
-class Tracing {
-  enabled = false;
-  categories = "";
+const { validateObject, validateString } = require("internal/validators");
+
+// Native bindings for trace events
+const { enableTraceEvents, disableTraceEvents, emitTraceEvent } = $cpp(
+  "NodeTraceEvents.cpp",
+  "createNodeTraceEventsBindings",
+);
+
+// Trace event categories that were enabled via CLI
+let globalCategories = "";
+
+// Initialize trace events if enabled via CLI
+const trace_categories = Bun.env.NODE_TRACE_EVENT_CATEGORIES;
+if (trace_categories) {
+  globalCategories = trace_categories;
+  enableTraceEvents(globalCategories);
+
+  // Emit initial environment trace event
+  emitTraceEvent("Environment", "node.environment");
 }
 
-function createTracing(opts) {
-  if (typeof opts !== "object" || opts == null) {
-    // @ts-ignore
-    throw $ERR_INVALID_ARG_TYPE("options", "object", opts);
+function Tracing(options) {
+  validateObject(options, "options");
+
+  let categories = "";
+  if (options.categories !== undefined) {
+    if (Array.isArray(options.categories)) {
+      categories = options.categories.join(",");
+    } else {
+      validateString(options.categories, "options.categories");
+      categories = options.categories || "";
+    }
   }
 
-  // TODO: validate categories
-  // @ts-ignore
-  return new Tracing(opts);
+  let enabled = false;
+
+  return {
+    get enabled() {
+      return enabled;
+    },
+
+    get categories() {
+      return categories;
+    },
+
+    enable() {
+      if (enabled) return;
+      enabled = true;
+      enableTraceEvents(categories);
+    },
+
+    disable() {
+      if (!enabled) return;
+      enabled = false;
+      disableTraceEvents();
+    },
+  };
+}
+
+function createTracing(options) {
+  return Tracing(options);
 }
 
 function getEnabledCategories() {
-  return "";
+  // Return categories that were enabled via command line
+  return globalCategories;
 }
 
 export default {

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