builder: time the main steps in BuildUpdate

Add a small struct to count the time taken by the important steps of
BuildUpdate. This will make easier to compare when we move the steps
to use the new swupd implementation -- and might be useful to keep
even after that comparison is not needed.

Signed-off-by: Caio Marcelo de Oliveira Filho <caio.oliveira@intel.com>

builder/builder.go

@@ -524,6 +524,9 @@ func (b *Builder) BuildChroots(template *x509.Certificate, privkey *rsa.PrivateK
 
 // BuildUpdate will produce an update consumable by the swupd client
 func (b *Builder) BuildUpdate(prefixflag string, minVersion int, format string, skipSigning bool, publish bool, keepChroots bool) error {
+	var timer stopWatch
+	defer timer.WriteSummary(os.Stdout)
+
 	if format != "" {
 		b.Format = format
 	}
@@ -536,6 +539,7 @@ func (b *Builder) BuildUpdate(prefixflag string, minVersion int, format string,
 	}
 
 	// Create update metadata for the mix.
+	timer.Start("create update")
 	updatecmd := exec.Command(prefixflag+"swupd_create_update", "-S", b.Statedir, "--minversion", strconv.Itoa(minVersion), "-F", b.Format, "--osversion", b.Mixver)
 	updatecmd.Stdout = os.Stdout
 	updatecmd.Stderr = os.Stderr
@@ -543,6 +547,7 @@ func (b *Builder) BuildUpdate(prefixflag string, minVersion int, format string,
 	if err != nil {
 		return errors.Wrapf(err, "failed to create update metadata")
 	}
+	timer.Stop()
 
 	// Clean up the bundle chroots as only the full chroot is needed from this point on.
 	if !keepChroots {
@@ -573,6 +578,7 @@ func (b *Builder) BuildUpdate(prefixflag string, minVersion int, format string,
 	}
 
 	// Create full files.
+	timer.Start("create fullfiles")
 	fullfilecmd := exec.Command(prefixflag+"swupd_make_fullfiles", "-S", b.Statedir, b.Mixver)
 	fullfilecmd.Stdout = os.Stdout
 	fullfilecmd.Stderr = os.Stderr
@@ -580,8 +586,10 @@ func (b *Builder) BuildUpdate(prefixflag string, minVersion int, format string,
 	if err != nil {
 		return errors.Wrapf(err, "couldn't create fullfiles")
 	}
+	timer.Stop()
 
 	// Create zero packs.
+	timer.Start("create zero packs")
 	zeropackArgs := []string{"--to", b.Mixver, "-S", b.Statedir}
 	if prefixflag != "" {
 		zeropackArgs = append(zeropackArgs, "--repodir", prefixflag)
@@ -593,8 +601,10 @@ func (b *Builder) BuildUpdate(prefixflag string, minVersion int, format string,
 	if err != nil {
 		return errors.Wrapf(err, "couldn't create zero packs")
 	}
+	timer.Stop()
 
 	// Hardlink the duplicate files. This helps when keeping the bundle chroots.
+	timer.Start("hardlink")
 	hardlinkcmd := exec.Command("hardlink", "-f", b.Statedir+"/image/"+b.Mixver+"/")
 	hardlinkcmd.Stdout = os.Stdout
 	hardlinkcmd.Stderr = os.Stderr
@@ -602,6 +612,7 @@ func (b *Builder) BuildUpdate(prefixflag string, minVersion int, format string,
 	if err != nil {
 		return errors.Wrapf(err, "couldn't perform hardlink step")
 	}
+	timer.Stop()
 
 	// Save upstream information.
 	if b.Upstreamurl != "" {

builder/stopwatch.go

@@ -0,0 +1,65 @@
+package builder
+
+import (
+	"fmt"
+	"io"
+	"time"
+)
+
+// stopWatch keeps track of a sequence of durations. Use Start and Stop to mark the sections, then
+// write the final result with WriteSummary.
+type stopWatch struct {
+	entries []stopWatchEntry
+	t       time.Time
+	w       io.Writer
+}
+
+type stopWatchEntry struct {
+	name string
+	d    time.Duration
+	used bool
+}
+
+func (sw *stopWatch) Start(name string) {
+	if sw.w != nil {
+		if len(sw.entries) > 0 {
+			fmt.Println()
+		}
+		fmt.Fprintf(sw.w, "=> %s\n", name)
+	}
+	sw.entries = append(sw.entries, stopWatchEntry{name: name})
+	sw.t = time.Now()
+}
+
+func (sw *stopWatch) Stop() {
+	if len(sw.entries) == 0 {
+		return
+	}
+	last := len(sw.entries) - 1
+	if sw.entries[last].used {
+		sw.entries = append(sw.entries, sw.entries[last])
+		last++
+	}
+	e := &sw.entries[last]
+	e.used = true
+	e.d = time.Since(sw.t)
+}
+
+func (sw *stopWatch) WriteSummary(w io.Writer) {
+	if len(sw.entries) == 0 {
+		return
+	}
+	max := 0
+	for _, e := range sw.entries {
+		if len(e.name) > max {
+			max = len(e.name)
+		}
+	}
+	var sum time.Duration
+	fmt.Fprintf(w, "\nTIMINGS\n")
+	for _, e := range sw.entries {
+		fmt.Fprintf(w, "  %-*s %s\n", max, e.name, e.d.Truncate(time.Millisecond))
+		sum += e.d
+	}
+	fmt.Fprintf(w, "TOTAL: %s\n", sum.Truncate(time.Millisecond))
+}