many: metrics option for stage durations

This commit introduces a new metrics option for the image building
stages, allowing users to get more insights into the duration of each
stage.

Author: lzap

cmd/image-builder/build.go

@@ -17,6 +17,7 @@ type buildOptions struct {
 
 	WriteManifest bool
 	WriteBuildlog bool
+	Metrics       bool
 }
 
 func buildImage(pbar progress.ProgressBar, res *imagefilter.Result, osbuildManifest []byte, opts *buildOptions) (string, error) {
@@ -38,6 +39,7 @@ func buildImage(pbar progress.ProgressBar, res *imagefilter.Result, osbuildManif
 	osbuildOpts := &progress.OSBuildOptions{
 		StoreDir:  opts.StoreDir,
 		OutputDir: opts.OutputDir,
+		Metrics:   opts.Metrics,
 	}
 	if opts.WriteBuildlog {
 		if err := os.MkdirAll(opts.OutputDir, 0755); err != nil {

cmd/image-builder/main.go

@@ -374,6 +374,10 @@ func cmdBuild(cmd *cobra.Command, args []string) error {
 	if err != nil {
 		return err
 	}
+	withMetrics, err := cmd.Flags().GetBool("with-metrics")
+	if err != nil {
+		return err
+	}
 	// XXX: check env here, i.e. if user is root and osbuild is installed
 
 	// Setup osbuild environment if running in a container
@@ -432,6 +436,7 @@ func cmdBuild(cmd *cobra.Command, args []string) error {
 		StoreDir:       cacheDir,
 		WriteManifest:  withManifest,
 		WriteBuildlog:  withBuildlog,
+		Metrics:        withMetrics,
 	}
 	pbar.SetPulseMsgf("Image building step")
 	imagePath, err := buildImage(pbar, res, mf.Bytes(), buildOpts)
@@ -595,6 +600,7 @@ operating systems like Fedora, CentOS and RHEL with easy customizations support.
 	// XXX: add "--verbose" here, similar to how bib is doing this
 	// (see https://github.com/osbuild/bootc-image-builder/pull/790/commits/5cec7ffd8a526e2ca1e8ada0ea18f927695dfe43)
 	buildCmd.Flags().String("progress", "auto", "type of progress bar to use (e.g. verbose,term)")
+	buildCmd.Flags().Bool("with-metrics", false, `print timing information at the end of the build`)
 	buildCmd.Flags().String("output-name", "", "set specific output basename")
 	rootCmd.AddCommand(buildCmd)
 	buildCmd.Flags().AddFlagSet(uploadCmd.Flags())

pkg/progress/command.go

@@ -25,6 +25,8 @@ type OSBuildOptions struct {
 	BuildLog io.Writer
 
 	CacheMaxSize int64
+
+	Metrics bool
 }
 
 // XXX: merge variant back into images/pkg/osbuild/osbuild-exec.go
@@ -154,6 +156,7 @@ func runOSBuildWithProgress(pb ProgressBar, manifest []byte, exports []string, o
 	}()
 
 	var tracesMsgs []string
+	oss := osbuildStageMetrics{}
 	for {
 		st, err := osbuildStatus.Status()
 		if err != nil {
@@ -192,11 +195,21 @@ func runOSBuildWithProgress(pb ProgressBar, manifest []byte, exports []string, o
 			tracesMsgs = append(tracesMsgs, st.Trace)
 			fmt.Fprintln(buildLog, st.Trace)
 		}
+
+		// store metrics if requested
+		if opts.Metrics {
+			oss.Add(st)
+		}
 	}
 
 	if err := cmd.Wait(); err != nil {
 		return fmt.Errorf("error running osbuild: %w\nBuildLog:\n%s\nOutput:\n%s", err, strings.Join(tracesMsgs, "\n"), stdio.String())
 	}
 
+	// append metrics to the end message
+	if opts.Metrics {
+		pb.Write(oss.Bytes())
+	}
+
 	return nil
 }

pkg/progress/metrics.go

@@ -0,0 +1,53 @@
+package progress
+
+import (
+	"sort"
+	"time"
+
+	"github.com/osbuild/images/pkg/osbuild"
+)
+
+type osbuildStageMetrics struct {
+	durations []measurement
+}
+
+type measurement struct {
+	Pipeline string
+	Name     string
+	Duration time.Duration
+}
+
+func (s *osbuildStageMetrics) Add(st *osbuild.Status) {
+	if st.Duration > 1*time.Second && st.Message != "" {
+		s.durations = append(s.durations, measurement{
+			Pipeline: st.Pipeline,
+			Name:     st.Message,
+			Duration: st.Duration,
+		})
+	}
+}
+
+func (s *osbuildStageMetrics) String() string {
+	if len(s.durations) == 0 {
+		return ""
+	}
+
+	// sort measurements by duration descending
+	sort.Slice(s.durations, func(i, j int) bool {
+		return s.durations[i].Duration > s.durations[j].Duration
+	})
+
+	result := "Metrics:\n"
+	for i, m := range s.durations {
+		result += "\t" + m.Pipeline + ": " + m.Name + ": " + m.Duration.Truncate(time.Second).String() + "\n"
+		if i >= 9 {
+			break
+		}
+	}
+
+	return result
+}
+
+func (s *osbuildStageMetrics) Bytes() []byte {
+	return []byte(s.String())
+}