add better timing tracking to generate command

cmd/generate.go

@@ -2,17 +2,17 @@ package cmd
 
 import (
 	"fmt"
-	dbGen2 "github.com/keenmate/db-gen/private/dbGen"
-	common2 "github.com/keenmate/db-gen/private/helpers"
+	"github.com/keenmate/db-gen/private/dbGen"
+	"github.com/keenmate/db-gen/private/helpers"
 	"github.com/spf13/cobra"
 	"github.com/spf13/viper"
 	"log"
 )
 
 const keyUseRoutinesFile = "useRoutinesFile"
 
-var generateFlags = []common2.FlagArgument{
-	common2.NewBoolFlag(keyUseRoutinesFile, "", false, "Use routines file to generate code"),
+var generateFlags = []helpers.FlagArgument{
+	helpers.NewBoolFlag(keyUseRoutinesFile, "", false, "Use routines file to generate code"),
 }
 
 var generateCmd = &cobra.Command{
@@ -27,74 +27,85 @@ var generateCmd = &cobra.Command{
 
 	`,
 	Run: func(cmd *cobra.Command, args []string) {
-		common2.BindFlags(cmd, append(commonFlags, generateFlags...))
-		_, err := dbGen2.ReadConfig(viper.GetString(keyConfig))
+		helpers.BindFlags(cmd, append(commonFlags, generateFlags...))
+		_, err := dbGen.ReadConfig(viper.GetString(keyConfig))
 		if err != nil {
-			common2.Exit("configuration error: %s", err)
+			helpers.Exit("configuration error: %s", err)
 		}
 
 		viper.AutomaticEnv() // read in environment variables that match
 
 		err = doGenerate()
 		if err != nil {
-			common2.Exit(err.Error())
+			helpers.Exit(err.Error())
 		}
 	},
 }
 
 func init() {
 	rootCmd.AddCommand(generateCmd)
 
-	common2.DefineFlags(generateCmd, append(commonFlags, generateFlags...))
+	helpers.DefineFlags(generateCmd, append(commonFlags, generateFlags...))
 }
 
 func doGenerate() error {
+	timer := helpers.NewTimer()
 	log.Printf("Getting configurations...")
 
-	config, err := dbGen2.GetAndValidateConfig()
+	config, err := dbGen.GetAndValidateConfig()
 	if err != nil {
 		return fmt.Errorf("error getting config %s", err)
 	}
 
-	common2.LogDebug("Debug logging is enabled")
+	helpers.LogDebug("Debug logging is enabled")
+	timer.AddEntry("getting config")
 
-	var routines []dbGen2.DbRoutine
+	var routines []dbGen.DbRoutine
 
 	log.Printf("Getting routines...")
-	routines, err = dbGen2.GetRoutines(config)
+	routines, err = dbGen.GetRoutines(config)
 	if err != nil {
 		return fmt.Errorf("error getting routines: %s", err)
 	}
 	log.Printf("Got %d routines", len(routines))
 
+	timer.AddEntry("getting routines")
 	if config.Debug {
-		common2.LogDebug("Saving to debug file...")
-		err = common2.SaveToTempFile(routines, "dbRoutines")
+		helpers.LogDebug("Saving to debug file...")
+		err = helpers.SaveToTempFile(routines, "dbRoutines")
 		if err != nil {
 			return fmt.Errorf("error saving debug file: %s", err)
 		}
+		timer.AddEntry("saving debug file")
+
 	}
 
 	log.Printf("Preprocessing...")
-	processedFunctions, err := dbGen2.Process(routines, config)
+	processedFunctions, err := dbGen.Process(routines, config)
 	if err != nil {
 		return fmt.Errorf("error preprocessing: %s", err)
 	}
 	log.Printf("After preprocessing %d - %d = %d functions left", len(routines), len(routines)-len(processedFunctions), len(processedFunctions))
+	timer.AddEntry("preprocessing")
 
 	if config.Debug {
-		common2.LogDebug("Saving to debug file...")
-		err = common2.SaveToTempFile(processedFunctions, "mapped")
+		helpers.LogDebug("Saving to debug file...")
+		err = helpers.SaveToTempFile(processedFunctions, "mapped")
 		if err != nil {
 			return fmt.Errorf("error saving debug file: %s", err)
 		}
+		timer.AddEntry("saving debug file")
+
 	}
 
 	log.Printf("Generating...")
-	err = dbGen2.Generate(processedFunctions, config)
+	err = dbGen.Generate(processedFunctions, config)
 	if err != nil {
 		return fmt.Errorf("error generating: %s", err)
 	}
 
+	timer.AddEntry("generating files")
+	timer.Finish()
+	log.Printf(timer.String())
 	return nil
 }

private/helpers/timer.go

@@ -0,0 +1,50 @@
+package helpers
+
+import (
+	"fmt"
+	"strings"
+	"time"
+)
+
+type entry struct {
+	time  time.Time
+	label string
+}
+
+type Timer struct {
+	timers []entry
+}
+
+func NewTimer() *Timer {
+	timer := &Timer{timers: []entry{}}
+	timer.AddEntry("start")
+
+	return timer
+}
+
+func (t *Timer) Finish() {
+	t.AddEntry("finish")
+}
+
+func (t *Timer) String() string {
+	if len(t.timers) < 2 {
+		return "Timer not stopped"
+	}
+	var str strings.Builder
+
+	startTime := t.timers[0].time
+	endTime := t.timers[len(t.timers)-1].time
+	totalExecTime := endTime.Sub(startTime)
+	str.WriteString(fmt.Sprintf("Total execution time %s \n", totalExecTime))
+
+	for i, entry := range t.timers[1 : len(t.timers)-1] {
+		sinceLast := entry.time.Sub(t.timers[i].time)
+		sinceStart := entry.time.Sub(startTime)
+		str.WriteString(fmt.Sprintf("   %s: %s (%s)\n", entry.label, sinceLast, sinceStart))
+	}
+	return str.String()
+}
+
+func (t *Timer) AddEntry(label string) {
+	t.timers = append(t.timers, entry{time: time.Now(), label: label})
+}