From 0ed34e3cb0b45af5579cf6905cf3b077b4cf2c43 Mon Sep 17 00:00:00 2001
From: Dan Kegel <dkegel@fastly.com>
Date: Fri, 14 Jan 2022 09:25:40 -0800
Subject: [PATCH] testing: print duration

TODO: account for time taken in Cleanup().
---
 main_test.go           |  6 ++++++
 src/testing/testing.go | 49 ++++++++++++++++++++++++++++--------------
 testdata/testing.txt   |  4 ++--
 3 files changed, 41 insertions(+), 18 deletions(-)

diff --git a/main_test.go b/main_test.go
index d83448bf..29095583 100644
--- a/main_test.go
+++ b/main_test.go
@@ -15,6 +15,7 @@ import (
 	"os"
 	"os/exec"
 	"path/filepath"
+	"regexp"
 	"runtime"
 	"strings"
 	"sync"
@@ -426,6 +427,11 @@ func runTestWithConfig(name string, t *testing.T, options compileopts.Options, c
 		actual = bytes.Replace(actual, []byte{0x1b, '[', '0', 'm'}, nil, -1)
 		actual = bytes.Replace(actual, []byte{'.', '.', '\n'}, []byte{'\n'}, -1)
 	}
+	if name == "testing.go" {
+		// Strip actual time.
+		re := regexp.MustCompile(`\([0-9]\.[0-9][0-9]s\)`)
+		actual = re.ReplaceAllLiteral(actual, []byte{'(', '0', '.', '0', '0', 's', ')'})
+	}
 
 	// Check whether the command ran successfully.
 	fail := false
diff --git a/src/testing/testing.go b/src/testing/testing.go
index ec5d2d44..599ca258 100644
--- a/src/testing/testing.go
+++ b/src/testing/testing.go
@@ -15,6 +15,7 @@ import (
 	"io"
 	"os"
 	"strings"
+	"time"
 )
 
 // Testing flags.
@@ -51,9 +52,11 @@ type common struct {
 	cleanups []func() // optional functions to be called at the end of the test
 	finished bool     // Test function has completed.
 
-	parent *common
-	level  int    // Nesting depth of test or benchmark.
-	name   string // Name of test or benchmark.
+	parent   *common
+	level    int       // Nesting depth of test or benchmark.
+	name     string    // Name of test or benchmark.
+	start    time.Time // Time test or benchmark started
+	duration time.Duration
 }
 
 // Short reports whether the -test.short flag is set.
@@ -73,6 +76,11 @@ func Verbose() bool {
 	return flagVerbose
 }
 
+// fmtDuration returns a string representing d in the form "87.00s".
+func fmtDuration(d time.Duration) string {
+	return fmt.Sprintf("%.2fs", d.Seconds())
+}
+
 // TB is the interface common to T and B.
 type TB interface {
 	Error(args ...interface{})
@@ -265,21 +273,11 @@ func tRunner(t *T, fn func(t *T)) {
 		fmt.Fprintf(t.w, "=== RUN   %s\n", t.name)
 	}
 
+	t.start = time.Now()
 	fn(t)
+	t.duration += time.Since(t.start) // TODO: capture cleanup time, too.
 
-	// Process the result (pass or fail).
-	if t.failed {
-		if t.parent != nil {
-			t.parent.failed = true
-		}
-		fmt.Fprintf(t.w, t.indent+"--- FAIL: %s\n", t.name)
-		t.w.Write(t.output.Bytes())
-	} else {
-		if flagVerbose {
-			fmt.Fprintf(t.w, t.indent+"--- PASS: %s\n", t.name)
-			t.w.Write(t.output.Bytes())
-		}
-	}
+	t.report() // Report after all subtests have finished.
 }
 
 // Run runs f as a subtest of t called name. It waits until the subtest is finished
@@ -381,6 +379,25 @@ func (m *M) Run() int {
 	return failures
 }
 
+func (t *T) report() {
+	dstr := fmtDuration(t.duration)
+	format := t.indent + "--- %s: %s (%s)\n"
+	if t.Failed() {
+		if t.parent != nil {
+			t.parent.failed = true
+		}
+		fmt.Fprintf(t.w, format, "FAIL", t.name, dstr)
+		t.w.Write(t.output.Bytes())
+	} else if flagVerbose {
+		if t.Skipped() {
+			fmt.Fprintf(t.w, format, "SKIP", t.name, dstr)
+		} else {
+			fmt.Fprintf(t.w, format, "PASS", t.name, dstr)
+		}
+		t.w.Write(t.output.Bytes())
+	}
+}
+
 // AllocsPerRun returns the average number of allocations during calls to f.
 // Although the return value has type float64, it will always be an integral
 // value.
diff --git a/testdata/testing.txt b/testdata/testing.txt
index 816246c2..814ddff3 100644
--- a/testdata/testing.txt
+++ b/testdata/testing.txt
@@ -1,10 +1,10 @@
---- FAIL: TestBar
+--- FAIL: TestBar (0.00s)
     log Bar
     log g
         h
         i
         
-    --- FAIL: TestBar/Bar2
+    --- FAIL: TestBar/Bar2 (0.00s)
         log Bar2
             a
             b