[bun test] Add timings to successful tests

3 files changed, 74 insertions, 13 deletions

diff --git a/src/bun.js/test/jest.zig b/src/bun.js/test/jest.zig
index 9bfc95811..ed4741f1f 100644
--- a/src/bun.js/test/jest.zig
+++ b/src/bun.js/test/jest.zig
@@ -348,6 +348,8 @@ pub const DiffFormatter = struct {
 };
 
 const ArrayIdentityContext = @import("../../identity_context.zig").ArrayIdentityContext;
+pub var test_elapsed_timer: ?*std.time.Timer = null;
+
 pub const TestRunner = struct {
     tests: TestRunner.Test.List = .{},
     log: *logger.Log,
@@ -421,7 +423,7 @@ pub const TestRunner = struct {
     pub const Callback = struct {
         pub const OnUpdateCount = *const fn (this: *Callback, delta: u32, total: u32) void;
         pub const OnTestStart = *const fn (this: *Callback, test_id: Test.ID) void;
-        pub const OnTestUpdate = *const fn (this: *Callback, test_id: Test.ID, file: string, label: string, expectations: u32, parent: ?*DescribeScope) void;
+        pub const OnTestUpdate = *const fn (this: *Callback, test_id: Test.ID, file: string, label: string, expectations: u32, elapsed_ns: u64, parent: ?*DescribeScope) void;
         onUpdateCount: OnUpdateCount,
         onTestStart: OnTestStart,
         onTestPass: OnTestUpdate,
@@ -429,18 +431,18 @@ pub const TestRunner = struct {
         onTestSkip: OnTestUpdate,
     };
 
-    pub fn reportPass(this: *TestRunner, test_id: Test.ID, file: string, label: string, expectations: u32, parent: ?*DescribeScope) void {
+    pub fn reportPass(this: *TestRunner, test_id: Test.ID, file: string, label: string, expectations: u32, elapsed_ns: u64, parent: ?*DescribeScope) void {
         this.tests.items(.status)[test_id] = .pass;
-        this.callback.onTestPass(this.callback, test_id, file, label, expectations, parent);
+        this.callback.onTestPass(this.callback, test_id, file, label, expectations, elapsed_ns, parent);
     }
     pub fn reportFailure(this: *TestRunner, test_id: Test.ID, file: string, label: string, expectations: u32, parent: ?*DescribeScope) void {
         this.tests.items(.status)[test_id] = .fail;
-        this.callback.onTestFail(this.callback, test_id, file, label, expectations, parent);
+        this.callback.onTestFail(this.callback, test_id, file, label, expectations, 0, parent);
     }
 
     pub fn reportSkip(this: *TestRunner, test_id: Test.ID, file: string, label: string, parent: ?*DescribeScope) void {
         this.tests.items(.status)[test_id] = .skip;
-        this.callback.onTestSkip(this.callback, test_id, file, label, 0, parent);
+        this.callback.onTestSkip(this.callback, test_id, file, label, 0, 0, parent);
     }
 
     pub fn addTestCount(this: *TestRunner, count: u32) u32 {
@@ -3129,6 +3131,12 @@ pub const TestScope = struct {
             .parent = DescribeScope.active,
         }) catch unreachable;
 
+        if (test_elapsed_timer == null) create_tiemr: {
+            var timer = bun.default_allocator.create(std.time.Timer) catch unreachable;
+            timer.* = std.time.Timer.start() catch break :create_tiemr;
+            test_elapsed_timer = timer;
+        }
+
         return this;
     }
 
@@ -3195,6 +3203,10 @@ pub const TestScope = struct {
         const callback_length = JSValue.fromRef(callback).getLengthOfArray(vm.global);
 
         var initial_value = JSValue.zero;
+        if (test_elapsed_timer) |timer| {
+            timer.reset();
+        }
+
         if (callback_length > 0) {
             const callback_func = JSC.NewFunctionWithData(
                 vm.global,
@@ -3871,7 +3883,17 @@ pub const TestRunnerTask = struct {
 
     fn processTestResult(this: *TestRunnerTask, globalThis: *JSC.JSGlobalObject, result: Result, test_: TestScope, test_id: u32, describe: *DescribeScope) void {
         switch (result) {
-            .pass => |count| Jest.runner.?.reportPass(test_id, this.source_file_path, test_.label, count, describe),
+            .pass => |count| Jest.runner.?.reportPass(
+                test_id,
+                this.source_file_path,
+                test_.label,
+                count,
+                if (test_elapsed_timer) |timer|
+                    timer.read()
+                else
+                    0,
+                describe,
+            ),
             .fail => |count| Jest.runner.?.reportFailure(test_id, this.source_file_path, test_.label, count, describe),
             .skip => Jest.runner.?.reportSkip(test_id, this.source_file_path, test_.label, describe),
             .pending => @panic("Unexpected pending test"),
diff --git a/src/cli/test_command.zig b/src/cli/test_command.zig
index 4ae14dd26..fb73b0a15 100644
--- a/src/cli/test_command.zig
+++ b/src/cli/test_command.zig
@@ -99,7 +99,7 @@ pub const CommandLineReporter = struct {
         // var this: *CommandLineReporter = @fieldParentPtr(CommandLineReporter, "callback", cb);
     }
 
-    fn printTestLine(label: string, parent: ?*jest.DescribeScope, comptime skip: bool, writer: anytype) void {
+    fn printTestLine(label: string, elapsed_ns: u64, parent: ?*jest.DescribeScope, comptime skip: bool, writer: anytype) void {
         var scopes_stack = std.BoundedArray(*jest.DescribeScope, 64).init(0) catch unreachable;
         var parent_ = parent;
 
@@ -144,10 +144,19 @@ pub const CommandLineReporter = struct {
         else
             writer.print(comptime Output.prettyFmt(" {s}", false), .{display_label}) catch unreachable;
 
+        if (elapsed_ns > (std.time.ns_per_us * 10)) {
+            writer.print(" {any}", .{
+                Output.ElapsedFormatter{
+                    .colors = Output.enable_ansi_colors_stderr,
+                    .duration_ns = elapsed_ns,
+                },
+            }) catch unreachable;
+        }
+
         writer.writeAll("\n") catch unreachable;
     }
 
-    pub fn handleTestPass(cb: *TestRunner.Callback, id: Test.ID, _: string, label: string, expectations: u32, parent: ?*jest.DescribeScope) void {
+    pub fn handleTestPass(cb: *TestRunner.Callback, id: Test.ID, _: string, label: string, expectations: u32, elapsed_ns: u64, parent: ?*jest.DescribeScope) void {
         var writer_: std.fs.File.Writer = Output.errorWriter();
         var buffered_writer = std.io.bufferedWriter(writer_);
         var writer = buffered_writer.writer();
@@ -157,14 +166,14 @@ pub const CommandLineReporter = struct {
 
         writeTestStatusLine(.pass, &writer);
 
-        printTestLine(label, parent, false, writer);
+        printTestLine(label, elapsed_ns, parent, false, writer);
 
         this.jest.tests.items(.status)[id] = TestRunner.Test.Status.pass;
         this.summary.pass += 1;
         this.summary.expectations += expectations;
     }
 
-    pub fn handleTestFail(cb: *TestRunner.Callback, id: Test.ID, _: string, label: string, expectations: u32, parent: ?*jest.DescribeScope) void {
+    pub fn handleTestFail(cb: *TestRunner.Callback, id: Test.ID, _: string, label: string, expectations: u32, elapsed_ns: u64, parent: ?*jest.DescribeScope) void {
         var writer_: std.fs.File.Writer = Output.errorWriter();
         var this: *CommandLineReporter = @fieldParentPtr(CommandLineReporter, "callback", cb);
 
@@ -174,7 +183,7 @@ pub const CommandLineReporter = struct {
         var writer = this.failures_to_repeat_buf.writer(bun.default_allocator);
 
         writeTestStatusLine(.fail, &writer);
-        printTestLine(label, parent, false, writer);
+        printTestLine(label, elapsed_ns, parent, false, writer);
 
         writer_.writeAll(this.failures_to_repeat_buf.items[initial_length..]) catch unreachable;
         Output.flush();
@@ -185,7 +194,7 @@ pub const CommandLineReporter = struct {
         this.jest.tests.items(.status)[id] = TestRunner.Test.Status.fail;
     }
 
-    pub fn handleTestSkip(cb: *TestRunner.Callback, id: Test.ID, _: string, label: string, expectations: u32, parent: ?*jest.DescribeScope) void {
+    pub fn handleTestSkip(cb: *TestRunner.Callback, id: Test.ID, _: string, label: string, expectations: u32, elapsed_ns: u64, parent: ?*jest.DescribeScope) void {
         var writer_: std.fs.File.Writer = Output.errorWriter();
         var this: *CommandLineReporter = @fieldParentPtr(CommandLineReporter, "callback", cb);
 
@@ -197,7 +206,7 @@ pub const CommandLineReporter = struct {
             var writer = this.skips_to_repeat_buf.writer(bun.default_allocator);
 
             writeTestStatusLine(.skip, &writer);
-            printTestLine(label, parent, true, writer);
+            printTestLine(label, elapsed_ns, parent, true, writer);
 
             writer_.writeAll(this.skips_to_repeat_buf.items[initial_length..]) catch unreachable;
             Output.flush();
diff --git a/src/output.zig b/src/output.zig
index 4889111ab..0b0780bf8 100644
--- a/src/output.zig
+++ b/src/output.zig
@@ -251,6 +251,36 @@ pub fn flush() void {
     }
 }
 
+pub const ElapsedFormatter = struct {
+    colors: bool,
+    duration_ns: u64 = 0,
+
+    pub fn format(self: ElapsedFormatter, comptime _: []const u8, _: std.fmt.FormatOptions, writer_: anytype) !void {
+        switch (self.duration_ns) {
+            0...std.time.ns_per_ms * 10 => {
+                const fmt_str = "<r><d>[{d:>.2}ms<r><d>]<r>";
+                switch (self.colors) {
+                    inline else => |colors| try writer_.print(comptime prettyFmt(fmt_str, colors), .{@intToFloat(f64, self.duration_ns) / std.time.ns_per_ms}),
+                }
+            },
+            std.time.ns_per_ms * 8_000...std.math.maxInt(u64) => {
+                const fmt_str = "<r><d>[<r><yellow>{d:>.2}ms<r><d>]<r>";
+
+                switch (self.colors) {
+                    inline else => |colors| try writer_.print(comptime prettyFmt(fmt_str, colors), .{@intToFloat(f64, self.duration_ns) / std.time.ns_per_ms}),
+                }
+            },
+            else => {
+                const fmt_str = "<r><d>[<b>{d:>.2}ms<r><d>]<r>";
+
+                switch (self.colors) {
+                    inline else => |colors| try writer_.print(comptime prettyFmt(fmt_str, colors), .{@intToFloat(f64, self.duration_ns) / std.time.ns_per_ms}),
+                }
+            },
+        }
+    }
+};
+
 inline fn printElapsedToWithCtx(elapsed: f64, comptime printerFn: anytype, comptime has_ctx: bool, ctx: anytype) void {
     switch (@floatToInt(i64, @round(elapsed))) {
         0...1500 => {