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

diff --git a/commands/commandeer.go b/commands/commandeer.go
index b9e2ceef1da4d23a20a4f42298037195f2bd4e72..af711fdd68bd22a7baed01efa168481098e7b63d 100644 (file)
--- 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 3096e1fe023fe7b94827d9b78da0cef795dccfca..1b09a12a3e51ade0da1279efa58e0be074c1766a 100644 (file)
--- 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 3da059cc55a081e4bd5c90d38cecc8115536a394..7c831db5648934c678b25b051ddf7ab02201a4c4 100644 (file)
--- 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 8766e6aaf9704ae9ae547eb316775d9393f2f08e..2b2ddb4d1643820d1453c6a070b625dc53b6115e 100644 (file)
--- 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 a743df5bd46b72fb6c2a0cd1c1d6893826268c80..462cd6017fd4af3dbe97fb369c9935e47bdbbe8a 100644 (file)
--- 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 f5972a5b0393a881c748c1db946df7f831bd8552..5f377c6dd5fd0b1eb66e3ec79961ca6a64516a40 100644 (file)
--- 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