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

6 files changed, 55 insertions, 12 deletions

diff --git a/commands/commandeer.go b/commands/commandeer.go
index b9e2ceef1..af711fdd6 100644
--- a/commands/commandeer.go
+++ b/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,
diff --git a/commands/commands.go b/commands/commands.go
index 3096e1fe0..1b09a12a3 100644
--- a/commands/commands.go
+++ b/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)
diff --git a/commands/hugo.go b/commands/hugo.go
index 3da059cc5..7c831db56 100644
--- a/commands/hugo.go
+++ b/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)
diff --git a/common/loggers/loggers.go b/common/loggers/loggers.go
index 8766e6aaf..2b2ddb4d1 100644
--- a/common/loggers/loggers.go
+++ b/common/loggers/loggers.go
@@ -22,6 +22,7 @@ import (
 	"os"
 	"regexp"
 	"runtime"
+	"time"
 
 	"github.com/gohugoio/hugo/common/terminal"
 
@@ -41,6 +42,11 @@ func init() {
 // Logger wraps a *loggers.Logger and some other related logging state.
 type Logger struct {
 	*jww.Notepad
+
+	// The writer that represents stdout.
+	// Will be ioutil.Discard when in quiet mode.
+	Out io.Writer
+
 	ErrorCounter *jww.Counter
 	WarnCounter  *jww.Counter
 
@@ -48,6 +54,23 @@ type Logger struct {
 	errors *bytes.Buffer
 }
 
+// PrintTimerIfDelayed prints a time statement to the FEEDBACK logger
+// if considerable time is spent.
+func (l *Logger) PrintTimerIfDelayed(start time.Time, name string) {
+	elapsed := time.Since(start)
+	milli := int(1000 * elapsed.Seconds())
+	if milli < 500 {
+		return
+	}
+	l.FEEDBACK.Printf("%s in %v ms", name, milli)
+}
+
+func (l *Logger) PrintTimer(start time.Time, name string) {
+	elapsed := time.Since(start)
+	milli := int(1000 * elapsed.Seconds())
+	l.FEEDBACK.Printf("%s in %v ms", name, milli)
+}
+
 func (l *Logger) Errors() string {
 	if l.errors == nil {
 		return ""
@@ -186,6 +209,7 @@ func newLogger(stdoutThreshold, logThreshold jww.Threshold, outHandle, logHandle
 
 	return &Logger{
 		Notepad:      jww.NewNotepad(stdoutThreshold, logThreshold, outHandle, logHandle, "", log.Ldate|log.Ltime, listeners...),
+		Out:          outHandle,
 		ErrorCounter: errorCounter,
 		WarnCounter:  warnCounter,
 		errors:       errorBuff,
diff --git a/modules/client.go b/modules/client.go
index a743df5bd..462cd6017 100644
--- a/modules/client.go
+++ b/modules/client.go
@@ -259,7 +259,7 @@ func (c *Client) Vendor() error {
 
 // Get runs "go get" with the supplied arguments.
 func (c *Client) Get(args ...string) error {
-	if err := c.runGo(context.Background(), os.Stdout, append([]string{"get"}, args...)...); err != nil {
+	if err := c.runGo(context.Background(), c.logger.Out, append([]string{"get"}, args...)...); err != nil {
 		errors.Wrapf(err, "failed to get %q", args)
 	}
 	return nil
@@ -269,7 +269,7 @@ func (c *Client) Get(args ...string) error {
 // If path is empty, Go will try to guess.
 // If this succeeds, this project will be marked as Go Module.
 func (c *Client) Init(path string) error {
-	err := c.runGo(context.Background(), os.Stdout, "mod", "init", path)
+	err := c.runGo(context.Background(), c.logger.Out, "mod", "init", path)
 	if err != nil {
 		return errors.Wrap(err, "failed to init modules")
 	}
@@ -410,6 +410,8 @@ func (c *Client) runGo(
 		return nil
 	}
 
+	//defer c.logger.PrintTimer(time.Now(), fmt.Sprint(args))
+
 	stderr := new(bytes.Buffer)
 	cmd := exec.CommandContext(ctx, "go", args...)
 
diff --git a/modules/collect.go b/modules/collect.go
index f5972a5b0..5f377c6dd 100644
--- a/modules/collect.go
+++ b/modules/collect.go
@@ -19,6 +19,7 @@ import (
 	"os"
 	"path/filepath"
 	"strings"
+	"time"
 
 	"github.com/gohugoio/hugo/common/loggers"
 
@@ -468,7 +469,7 @@ func (c *collector) applyThemeConfig(tc *moduleAdapter) error {
 }
 
 func (c *collector) collect() {
-
+	defer c.logger.PrintTimerIfDelayed(time.Now(), "hugo: collected modules")
 	if err := c.initModules(); err != nil {
 		c.err = err
 		return