Merge pull request #221 from gitpod-io/wv/log-build-phase-durations

Log build phase durations

Author: WVerlaek

pkg/leeway/reporter.go

@@ -95,6 +95,10 @@ type ConsoleReporter struct {
 	writer map[string]io.Writer
 	times  map[string]time.Time
 	mu     sync.RWMutex
+
+	// out is the writer to print to. Normally this is os.Stdout, but it can be set to a buffer for testing.
+	out io.Writer
+	now func() time.Time
 }
 
 // exclusiveWriter makes a write an exclusive resource by protecting Write calls with a mutex.
@@ -115,6 +119,8 @@ func NewConsoleReporter() *ConsoleReporter {
 	return &ConsoleReporter{
 		writer: make(map[string]io.Writer),
 		times:  make(map[string]time.Time),
+		out:    os.Stdout,
+		now:    time.Now,
 	}
 }
 
@@ -134,7 +140,7 @@ func (r *ConsoleReporter) getWriter(pkg *Package) io.Writer {
 			return res
 		}
 
-		res = &exclusiveWriter{O: textio.NewPrefixWriter(os.Stdout, getRunPrefix(pkg))}
+		res = &exclusiveWriter{O: textio.NewPrefixWriter(r.out, getRunPrefix(pkg))}
 		r.writer[name] = res
 		r.mu.Unlock()
 	}
@@ -166,7 +172,7 @@ func (r *ConsoleReporter) BuildStarted(pkg *Package, status map[*Package]Package
 		i++
 	}
 	sort.Slice(lines, func(i, j int) bool { return lines[i] < lines[j] })
-	tw := tabwriter.NewWriter(os.Stdout, 0, 2, 2, ' ', 0)
+	tw := tabwriter.NewWriter(r.out, 0, 2, 2, ' ', 0)
 	fmt.Fprintln(tw, strings.Join(lines, ""))
 	tw.Flush()
 }
@@ -191,7 +197,7 @@ func (r *ConsoleReporter) PackageBuildStarted(pkg *Package) {
 	}
 
 	r.mu.Lock()
-	r.times[pkg.FullName()] = time.Now()
+	r.times[pkg.FullName()] = r.now()
 	r.mu.Unlock()
 
 	_, _ = io.WriteString(out, color.Sprintf("<fg=yellow>build started</> <gray>(version %s)</>\n", version))
@@ -210,20 +216,32 @@ func (r *ConsoleReporter) PackageBuildFinished(pkg *Package, rep *PackageBuildRe
 	out := r.getWriter(pkg)
 
 	r.mu.Lock()
-	dur := time.Since(r.times[nme])
+	dur := r.now().Sub(r.times[nme])
 	delete(r.writer, nme)
 	delete(r.times, nme)
 	r.mu.Unlock()
 
+	// Format phase durations
+	var phaseDurations []string
+	for _, phase := range rep.Phases {
+		if d := rep.PhaseDuration(phase); d > 0 {
+			phaseDurations = append(phaseDurations, fmt.Sprintf("%s: %.1fs", phase, d.Seconds()))
+		}
+	}
+	phaseDurStr := ""
+	if len(phaseDurations) > 0 {
+		phaseDurStr = color.Sprintf(" [%s]", strings.Join(phaseDurations, " | "))
+	}
+
 	var msg string
-  if rep.Error != nil {
+	if rep.Error != nil {
 		msg = color.Sprintf("<red>package build failed while %sing</>\n<white>Reason:</> %s\n", rep.LastPhase(), rep.Error)
 	} else {
 		var coverage string
 		if rep.TestCoverageAvailable {
 			coverage = color.Sprintf("<fg=yellow>test coverage: %d%%</> <gray>(%d of %d functions have tests)</>\n", rep.TestCoveragePercentage, rep.FunctionsWithTest, rep.FunctionsWithTest+rep.FunctionsWithoutTest)
 		}
-		msg = color.Sprintf("%s<green>package build succeded</> <gray>(%.2fs)</>\n", coverage, dur.Seconds())
+		msg = color.Sprintf("%s<green>package build succeded</> <gray>(%.2fs)%s</>\n", coverage, dur.Seconds(), phaseDurStr)
 	}
 	//nolint:errcheck
 	io.WriteString(out, msg)

pkg/leeway/reporter_test.go

@@ -0,0 +1,109 @@
+package leeway
+
+import (
+	"bytes"
+	"testing"
+	"time"
+
+	"github.com/google/go-cmp/cmp"
+)
+
+func TestConsoleReporter(t *testing.T) {
+	t.Parallel()
+
+	type Expectation struct {
+		Output string
+	}
+
+	start := time.Now()
+	pkg := &Package{
+		C: &Component{
+			Name: "test",
+		},
+		PackageInternal: PackageInternal{
+			Name: "test",
+		},
+	}
+
+	tests := []struct {
+		Name     string
+		Reporter Reporter
+		Func     func(t *testing.T, r *ConsoleReporter)
+		Expect   Expectation
+	}{
+		{
+			Name: "all phases",
+			Func: func(t *testing.T, r *ConsoleReporter) {
+				r.PackageBuildStarted(pkg)
+
+				r.now = func() time.Time {
+					return start.Add(5 * time.Second)
+				}
+				r.PackageBuildFinished(pkg, &PackageBuildReport{
+					Phases: []PackageBuildPhase{
+						PackageBuildPhasePrep,
+						PackageBuildPhasePull,
+						PackageBuildPhaseLint,
+						PackageBuildPhaseTest,
+						PackageBuildPhaseBuild},
+					phaseEnter: map[PackageBuildPhase]time.Time{
+						PackageBuildPhasePrep:  start,
+						PackageBuildPhasePull:  start.Add(time.Second),
+						PackageBuildPhaseBuild: start.Add(2 * time.Second),
+						PackageBuildPhaseTest:  start.Add(3 * time.Second),
+						PackageBuildPhaseLint:  start.Add(4 * time.Second),
+					},
+					phaseDone: map[PackageBuildPhase]time.Time{
+						PackageBuildPhasePrep:  start.Add(time.Second),
+						PackageBuildPhasePull:  start.Add(2 * time.Second),
+						PackageBuildPhaseBuild: start.Add(3 * time.Second),
+						PackageBuildPhaseTest:  start.Add(4 * time.Second),
+						PackageBuildPhaseLint:  start.Add(5 * time.Second),
+					},
+				})
+			},
+			Expect: Expectation{
+				Output: `[test:test] build started (version unknown)
+[test:test] package build succeded (5.00s) [prep: 1.0s | pull: 1.0s | lint: 1.0s | test: 1.0s | build: 1.0s]
+`,
+			},
+		},
+		{
+			Name: "no phases",
+			Func: func(t *testing.T, r *ConsoleReporter) {
+				r.PackageBuildStarted(pkg)
+				r.PackageBuildFinished(pkg, &PackageBuildReport{
+					Phases: []PackageBuildPhase{},
+				})
+			},
+			Expect: Expectation{
+				Output: `[test:test] build started (version unknown)
+[test:test] package build succeded (0.00s)
+`,
+			},
+		},
+	}
+
+	for _, test := range tests {
+		t.Run(test.Name, func(t *testing.T) {
+			t.Parallel()
+			var (
+				act Expectation
+				buf bytes.Buffer
+			)
+
+			reporter := NewConsoleReporter()
+			reporter.out = &buf
+			reporter.now = func() time.Time {
+				return start
+			}
+
+			test.Func(t, reporter)
+			act.Output = buf.String()
+
+			if diff := cmp.Diff(test.Expect.Output, act.Output); diff != "" {
+				t.Errorf("output mismatch (-want +got):\n%s", diff)
+			}
+		})
+	}
+}