Add some more output if loading modules takes time

Also include the time to collect modules etc. in the "Total in ..." time reported for the `hugo` command.

Fixes #6519

commands/commandeer.go

@@ -163,6 +163,11 @@ func newCommandeer(mustHaveConfigFile, running bool, h *hugoBuilderCommon, f fla
 		rebuildDebouncer = debounce.New(4 * time.Second)
 	}
 
+	out := ioutil.Discard
+	if !h.quiet {
+		out = os.Stdout
+	}
+
 	c := &commandeer{
 		h:                   h,
 		ftch:                f,
@@ -172,7 +177,7 @@ func newCommandeer(mustHaveConfigFile, running bool, h *hugoBuilderCommon, f fla
 		debounce:            rebuildDebouncer,
 		fullRebuildSem:      semaphore.NewWeighted(1),
 		// This will be replaced later, but we need something to log to before the configuration is read.
-		logger: loggers.NewLogger(jww.LevelError, jww.LevelError, os.Stdout, ioutil.Discard, running),
+		logger: loggers.NewLogger(jww.LevelError, jww.LevelError, out, ioutil.Discard, running),
 	}
 
 	return c, c.loadConfig(mustHaveConfigFile, running)
@@ -296,6 +301,7 @@ func (c *commandeer) loadConfig(mustHaveConfigFile, running bool) error {
 	config, configFiles, err := hugolib.LoadConfig(
 		hugolib.ConfigSourceDescriptor{
 			Fs:           sourceFs,
+			Logger:       c.logger,
 			Path:         configPath,
 			WorkingDir:   dir,
 			Filename:     c.h.cfgFile,

commands/commands.go

@@ -14,7 +14,9 @@
 package commands
 
 import (
+	"fmt"
 	"os"
+	"time"
 
 	"github.com/gohugoio/hugo/hugolib/paths"
 
@@ -146,6 +148,7 @@ built with love by spf13 and friends in Go.
 
 Complete documentation is available at http://gohugo.io/.`,
 		RunE: func(cmd *cobra.Command, args []string) error {
+			defer cc.timeTrack(time.Now(), "Total")
 			cfgInit := func(c *commandeer) error {
 				if cc.buildWatch {
 					c.Set("disableLiveReload", true)
@@ -216,6 +219,14 @@ type hugoBuilderCommon struct {
 	logFile string
 }
 
+func (cc *hugoBuilderCommon) timeTrack(start time.Time, name string) {
+	if cc.quiet {
+		return
+	}
+	elapsed := time.Since(start)
+	fmt.Printf("%s in %v ms\n", name, int(1000*elapsed.Seconds()))
+}
+
 func (cc *hugoBuilderCommon) getConfigDir(baseDir string) string {
 	if cc.cfgDir != "" {
 		return paths.AbsPathify(baseDir, cc.cfgDir)

commands/hugo.go

@@ -134,10 +134,14 @@ func (c *commandeer) createLogger(cfg config.Provider, running bool) (*loggers.L
 		logHandle       = ioutil.Discard
 		logThreshold    = jww.LevelWarn
 		logFile         = cfg.GetString("logFile")
-		outHandle       = os.Stdout
+		outHandle       = ioutil.Discard
 		stdoutThreshold = jww.LevelWarn
 	)
 
+	if !c.h.quiet {
+		outHandle = os.Stdout
+	}
+
 	if c.h.verboseLog || c.h.logging || (c.h.logFile != "") {
 		var err error
 		if logFile != "" {
@@ -463,8 +467,6 @@ func (c *commandeer) initProfiling() (func(), error) {
 }
 
 func (c *commandeer) build() error {
-	defer c.timeTrack(time.Now(), "Total")
-
 	stopProfiling, err := c.initProfiling()
 	if err != nil {
 		return err
@@ -519,7 +521,7 @@ func (c *commandeer) build() error {
 }
 
 func (c *commandeer) serverBuild() error {
-	defer c.timeTrack(time.Now(), "Total")
+	defer c.timeTrack(time.Now(), "Built")
 
 	stopProfiling, err := c.initProfiling()
 	if err != nil {
@@ -659,9 +661,6 @@ func (c *commandeer) firstPathSpec() *helpers.PathSpec {
 }
 
 func (c *commandeer) timeTrack(start time.Time, name string) {
-	if c.h.quiet {
-		return
-	}
 	elapsed := time.Since(start)
 	c.logger.FEEDBACK.Printf("%s in %v ms", name, int(1000*elapsed.Seconds()))
 }
@@ -773,7 +772,7 @@ func (c *commandeer) fullRebuild(changeType string) {
 			time.Sleep(2 * time.Second)
 		}()
 
-		defer c.timeTrack(time.Now(), "Total")
+		defer c.timeTrack(time.Now(), "Rebuilt")
 
 		c.commandeerHugoState = newCommandeerHugoState()
 		err := c.loadConfig(true, true)