ref: 2dcc1318d1d9ed849d040115aa5ba6191a1c102a
parent: 14a985f8abc527d4e8487fcd5fa742e1ab2a00ed
author: Bjørn Erik Pedersen <bjorn.erik.pedersen@gmail.com>
date: Thu Nov 21 08:07:52 EST 2019
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
--- a/commands/commandeer.go
+++ b/commands/commandeer.go
@@ -163,6 +163,11 @@
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 @@
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 @@
config, configFiles, err := hugolib.LoadConfig(
hugolib.ConfigSourceDescriptor{Fs: sourceFs,
+ Logger: c.logger,
Path: configPath,
WorkingDir: dir,
Filename: c.h.cfgFile,
--- 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 @@
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)@@ -214,6 +217,14 @@
cfgFile string
cfgDir string
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 {--- a/commands/hugo.go
+++ b/commands/hugo.go
@@ -134,10 +134,14 @@
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) build() error {- defer c.timeTrack(time.Now(), "Total")
-
stopProfiling, err := c.initProfiling()
if err != nil {return err
@@ -519,7 +521,7 @@
}
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) 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 @@
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)
--- a/common/loggers/loggers.go
+++ b/common/loggers/loggers.go
@@ -22,6 +22,7 @@
"os"
"regexp"
"runtime"
+ "time"
"github.com/gohugoio/hugo/common/terminal"
@@ -41,6 +42,11 @@
// 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 @@
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 @@
return &Logger{Notepad: jww.NewNotepad(stdoutThreshold, logThreshold, outHandle, logHandle, "", log.Ldate|log.Ltime, listeners...),
+ Out: outHandle,
ErrorCounter: errorCounter,
WarnCounter: warnCounter,
errors: errorBuff,
--- a/modules/client.go
+++ b/modules/client.go
@@ -259,7 +259,7 @@
// 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 @@
// 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")
}
@@ -409,6 +409,8 @@
if c.goBinaryStatus != 0 {return nil
}
+
+ //defer c.logger.PrintTimer(time.Now(), fmt.Sprint(args))
stderr := new(bytes.Buffer)
cmd := exec.CommandContext(ctx, "go", args...)
--- a/modules/collect.go
+++ b/modules/collect.go
@@ -19,6 +19,7 @@
"os"
"path/filepath"
"strings"
+ "time"
"github.com/gohugoio/hugo/common/loggers"
@@ -468,7 +469,7 @@
}
func (c *collector) collect() {-
+ defer c.logger.PrintTimerIfDelayed(time.Now(), "hugo: collected modules")
if err := c.initModules(); err != nil {c.err = err
return