Skip to content
Permalink
Browse files

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
  • Loading branch information
bep committed Nov 21, 2019
1 parent 14a985f commit 2dcc1318d1d9ed849d040115aa5ba6191a1c102a
Showing with 55 additions and 12 deletions.
  1. +7 −1 commands/commandeer.go
  2. +11 −0 commands/commands.go
  3. +7 −8 commands/hugo.go
  4. +24 −0 common/loggers/loggers.go
  5. +4 −2 modules/client.go
  6. +2 −1 modules/collect.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,
@@ -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)
@@ -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)
@@ -22,6 +22,7 @@ import (
"os"
"regexp"
"runtime"
"time"

"github.com/gohugoio/hugo/common/terminal"

@@ -41,13 +42,35 @@ 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

// This is only set in server mode.
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,
@@ -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...)

@@ -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

0 comments on commit 2dcc131

Please sign in to comment.
You can’t perform that action at this time.