add debug flag to print more build related metrics

bob/bob.go

@@ -27,6 +27,9 @@ type B struct {
 	// Repositories to track.
 	Repositories []Repo `yaml:"repositories"`
 
+	// debug enable debug putput
+	debug bool
+
 	// dir is bob's working directory.
 	dir string
 

bob/build.go

@@ -37,6 +37,7 @@ func (b *B) Build(ctx context.Context, taskName string) (err error) {
 		playbook.WithLocalStore(b.local),
 		playbook.WithPushEnabled(b.enablePush),
 		playbook.WithPullEnabled(b.enablePull),
+		playbook.WithDebug(b.debug),
 	)
 	errz.Fatal(err)
 

bob/options.go

@@ -88,3 +88,9 @@ func WithMaxParallel(maxParallel int) Option {
 		b.maxParallel = maxParallel
 	}
 }
+
+func WithDebug(debug bool) Option {
+	return func(b *B) {
+		b.debug = debug
+	}
+}

bob/playbook/build_internal.go

@@ -5,16 +5,20 @@ import (
 	"errors"
 	"fmt"
 	"io"
+	"time"
 
 	"github.com/benchkram/bob/bobtask"
+	"github.com/benchkram/bob/bobtask/processed"
 	"github.com/benchkram/bob/pkg/boblog"
 	"github.com/benchkram/errz"
 )
 
 // build a single task and update the playbook state after completion.
-func (p *Playbook) build(ctx context.Context, task *bobtask.Task) (err error) {
+func (p *Playbook) build(ctx context.Context, task *bobtask.Task) (_ processed.Task, err error) {
 	defer errz.Recover(&err)
 
+	pt := processed.Task{Task: task}
+
 	// A task is flagged successful before
 	var taskSuccessFul bool
 	var taskErr error
@@ -45,11 +49,15 @@ func (p *Playbook) build(ctx context.Context, task *bobtask.Task) (err error) {
 
 	// Filter inputs populates the task input member by reading and validating
 	// inputs with the filesystem.
+	start := time.Now()
 	err = task.FilterInputs()
 	errz.Fatal(err)
+	pt.FilterInputTook = time.Since(start)
 
+	start = time.Now()
 	rebuildRequired, rebuildCause, err := p.TaskNeedsRebuild(task.Name())
 	errz.Fatal(err)
+	pt.NeddRebuildTook = time.Since(start)
 	boblog.Log.V(2).Info(fmt.Sprintf("TaskNeedsRebuild [rebuildRequired: %t] [cause:%s]", rebuildRequired, rebuildCause))
 
 	// task might need a rebuild due to an input change.
@@ -107,18 +115,20 @@ func (p *Playbook) build(ctx context.Context, task *bobtask.Task) (err error) {
 		status := StateNoRebuildRequired
 		boblog.Log.V(2).Info(fmt.Sprintf("%-*s\t%s", p.namePad, coloredName, status.Short()))
 		taskSuccessFul = true
-		return p.TaskNoRebuildRequired(task.TaskID)
+		return pt, p.TaskNoRebuildRequired(task.TaskID)
 	}
 
 	err = task.Clean()
 	errz.Fatal(err)
 
+	start = time.Now()
 	err = task.Run(ctx, p.namePad)
 	if err != nil {
 		taskSuccessFul = false
 		taskErr = err
 	}
 	errz.Fatal(err)
+	pt.BuildTook = time.Since(start)
 
 	// FIXME: Is this placed correctly?
 	// Could also be done after the task completion is
@@ -128,19 +138,22 @@ func (p *Playbook) build(ctx context.Context, task *bobtask.Task) (err error) {
 	// flagged as failed in a defered function call.
 	taskSuccessFul = true
 
+	start = time.Now()
 	err = p.TaskCompleted(task.TaskID)
 	if err != nil {
 		if errors.Is(err, ErrFailed) {
-			return err
+			pt.CompletionTook = time.Since(start)
+			return pt, err
 		}
 	}
 	errz.Fatal(err)
+	pt.CompletionTook = time.Since(start)
 
 	taskStatus, err := p.TaskStatus(task.Name())
 	errz.Fatal(err)
 
 	state := taskStatus.State()
 	boblog.Log.V(1).Info(fmt.Sprintf("%-*s\t%s", p.namePad, coloredName, "..."+state.Short()))
 
-	return nil
+	return pt, nil
 }

bob/playbook/options.go

@@ -47,3 +47,9 @@ func WithLocalStore(s store.Store) Option {
 		p.localStore = s
 	}
 }
+
+func WithDebug(debug bool) Option {
+	return func(p *Playbook) {
+		p.debugSummary = debug
+	}
+}

bob/playbook/playbook.go

@@ -75,6 +75,9 @@ type Playbook struct {
 	// oncePrepareOptimizedAccess is used to initalize the optimized
 	// slice to access tasks.
 	oncePrepareOptimizedAccess sync.Once
+
+	// debugSummary print a more detailed summary when set
+	debugSummary bool
 }
 
 func New(root string, rootID int, opts ...Option) *Playbook {

bob/playbook/summary.go

@@ -2,15 +2,16 @@ package playbook
 
 import (
 	"fmt"
+	"time"
 
-	"github.com/benchkram/bob/bobtask"
+	"github.com/benchkram/bob/bobtask/processed"
 	"github.com/benchkram/bob/pkg/boblog"
 	"github.com/benchkram/bob/pkg/format"
 	"github.com/logrusorgru/aurora"
 )
 
 // summary prints the tasks processing details as a summary of the playbook.
-func (p *Playbook) summary(processedTasks []*bobtask.Task) {
+func (p *Playbook) summary(processedTasks []processed.Task) {
 
 	boblog.Log.V(1).Info("")
 	boblog.Log.V(1).Info(aurora.Bold("● ● ● ●").BrightGreen().String())
@@ -33,6 +34,20 @@ func (p *Playbook) summary(processedTasks []*bobtask.Task) {
 
 		taskName := t.Name()
 		boblog.Log.V(1).Info(fmt.Sprintf("  %-*s\t%s%s", p.namePad, taskName, status.Summary(), execTime))
+
+		if p.debugSummary {
+			pad := 15
+			printBuildDetails("filter-input", pad, t.FilterInputTook)
+			printBuildDetails("need-rebuild", pad, t.NeddRebuildTook)
+			printBuildDetails("build", pad, t.BuildTook)
+			printBuildDetails("completion", pad, t.CompletionTook)
+		}
+
 	}
 	boblog.Log.V(1).Info("")
 }
+
+func printBuildDetails(name string, pad int, duration time.Duration) {
+	d := fmt.Sprintf("\t(%s)", format.DisplayDuration(duration))
+	boblog.Log.V(1).Info(fmt.Sprintf("    %-*s %s", pad, name, d))
+}

bob/playbook/workers.go

@@ -6,7 +6,7 @@ import (
 	"sync"
 	"time"
 
-	"github.com/benchkram/bob/bobtask"
+	"github.com/benchkram/bob/bobtask/processed"
 )
 
 type workerManager struct {
@@ -27,7 +27,7 @@ type workerManager struct {
 	errors      []error
 
 	processedMutex sync.Mutex
-	processed      []*bobtask.Task
+	processed      []processed.Task
 
 	shutdownMutext sync.Mutex
 	shutdown       bool
@@ -40,7 +40,7 @@ func newWorkerManager() *workerManager {
 		workerState:    []string{},
 
 		errors:    []error{},
-		processed: []*bobtask.Task{},
+		processed: []processed.Task{},
 	}
 	return s
 }
@@ -73,7 +73,7 @@ func (wm *workerManager) addError(err error) {
 	wm.errorsMutex.Unlock()
 }
 
-func (wm *workerManager) addProcessedTask(t *bobtask.Task) {
+func (wm *workerManager) addProcessedTask(t processed.Task) {
 	wm.processedMutex.Lock()
 	wm.processed = append(wm.processed, t)
 	wm.processedMutex.Unlock()
@@ -131,7 +131,7 @@ func (p *Playbook) startWorkers(ctx context.Context, workers int) *workerManager
 
 				//boblog.Log.V(1).Info(fmt.Sprintf("RUNNING task %s on worker %d", t.Name(), workerID))
 
-				err := p.build(ctx, t.Task)
+				processedTask, err := p.build(ctx, t.Task)
 				if err != nil {
 					wm.addError(fmt.Errorf("(worker) [task: %s], %w", t.Name(), err))
 
@@ -151,7 +151,7 @@ func (p *Playbook) startWorkers(ctx context.Context, workers int) *workerManager
 					// }
 
 				}
-				wm.addProcessedTask(t.Task)
+				wm.addProcessedTask(processedTask)
 
 				//boblog.Log.V(1).Info(fmt.Sprintf("Done with task %s on worker  %d ", t.Name(), workerID))
 

bobtask/input.go

@@ -6,6 +6,7 @@ import (
 	"path/filepath"
 	"sort"
 	"strings"
+	"time"
 
 	"github.com/benchkram/bob/bob/global"
 	"github.com/benchkram/bob/pkg/file"
@@ -31,10 +32,14 @@ var (
 func (t *Task) FilterInputs() (err error) {
 	defer errz.Recover(&err)
 
+	start := time.Now()
+
 	inputs, err := t.FilteredInputs()
 	errz.Fatal(err)
 	t.inputs = inputs
 
+	fmt.Printf("filtering input for task %s took %s\n", t.name, time.Since(start).String())
+
 	return nil
 }
 
@@ -155,11 +160,11 @@ func (t *Task) FilteredInputs() ([]string, error) {
 
 	sort.Strings(sanitizedInputs)
 
-	//fmt.Println(t.name)
-	//fmt.Println("Inputs:", inputs)
+	// fmt.Println(t.name)
+	// fmt.Println("Inputs:", inputs)
 	// fmt.Println("Ignores:", ignores)
 	// fmt.Println("Filtered:", filteredInputs)
-	//fmt.Println("Sanitized:", sanitizedInputs)
+	// fmt.Println("Sanitized:", sanitizedInputs)
 	// fmt.Println("Sorted:", sortedInputs)
 
 	return sanitizedInputs, nil

bobtask/map.go

@@ -47,19 +47,16 @@ func (tm Map) Walk(root string, parentLevel string, fn func(taskname string, _ T
 	return nil
 }
 
-// func (tm Map) FilterInputs() (err error) {
-// 	defer errz.Recover(&err)
-
-// 	for key, task := range tm {
-// 		inputs, err := task.FilteredInputs()
-// 		errz.Fatal(err)
-// 		task.inputs = inputs
+func (tm Map) FilterInputs() (err error) {
+	defer errz.Recover(&err)
 
-// 		tm[key] = task
-// 	}
+	for _, task := range tm {
+		err = task.FilterInputs()
+		errz.Fatal(err)
+	}
 
-// 	return nil
-// }
+	return nil
+}
 
 // Sanitize task map and write filtered & sanitized
 // properties from dirty members to plain (e.g. dirtyInputs -> filter&sanitize -> inputs)

bobtask/processed/processed_task.go

@@ -0,0 +1,16 @@
+package processed
+
+import (
+	"time"
+
+	"github.com/benchkram/bob/bobtask"
+)
+
+type Task struct {
+	*bobtask.Task
+
+	FilterInputTook time.Duration
+	NeddRebuildTook time.Duration
+	BuildTook       time.Duration
+	CompletionTook  time.Duration
+}

cli/cmd_build.go

@@ -46,12 +46,15 @@ var buildCmd = &cobra.Command{
 		noPull, err := cmd.Flags().GetBool("no-pull")
 		errz.Fatal(err)
 
+		debug, err := cmd.Flags().GetBool("debug")
+		errz.Fatal(err)
+
 		taskname := global.DefaultBuildTask
 		if len(args) > 0 {
 			taskname = args[0]
 		}
 
-		runBuild(taskname, noCache, allowInsecure, enablePush, noPull, flagEnvVars, maxParallel)
+		runBuild(taskname, noCache, allowInsecure, enablePush, noPull, debug, flagEnvVars, maxParallel)
 	},
 	ValidArgsFunction: func(cmd *cobra.Command, args []string, toComplete string) ([]string, cobra.ShellCompDirective) {
 		tasks, err := getBuildTasks()
@@ -72,7 +75,7 @@ var buildListCmd = &cobra.Command{
 	},
 }
 
-func runBuild(taskname string, noCache, allowInsecure, enablePush, noPull bool, flagEnvVars []string, maxParallel int) {
+func runBuild(taskname string, noCache, allowInsecure, enablePush, noPull, debug bool, flagEnvVars []string, maxParallel int) {
 	var exitCode int
 	defer func() {
 		exit(exitCode)
@@ -86,6 +89,7 @@ func runBuild(taskname string, noCache, allowInsecure, enablePush, noPull bool,
 		bob.WithMaxParallel(maxParallel),
 		bob.WithPushEnabled(enablePush),
 		bob.WithPullEnabled(!noPull),
+		bob.WithDebug(debug),
 	)
 	if err != nil {
 		exitCode = 1

cli/cmd_root.go

@@ -54,6 +54,7 @@ func init() {
 	buildCmd.Flags().Bool("push", false, "Set to true to push artifacts to remote store")
 	buildCmd.Flags().Bool("no-pull", false, "Set to true to disable artifacts download from remote store")
 	buildCmd.Flags().Bool("insecure", false, "Set to true to use http instead of https when accessing a remote artifact store")
+	buildCmd.Flags().Bool("debug", false, "Enable debug output")
 	buildCmd.Flags().IntP("jobs", "j", runtime.NumCPU(), "Maximum number of parallel started jobs")
 	buildCmd.Flags().StringSliceVar(&flagEnvVars, "env", []string{}, "Set environment variables to build task")
 	buildCmd.AddCommand(buildListCmd)