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
This commit is contained in:
Bjørn Erik Pedersen 2019-11-21 13:07:52 +01:00
parent 14a985f8ab
commit 2dcc1318d1
6 changed files with 55 additions and 12 deletions

View file

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

View file

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

View file

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

View file

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

View file

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

View file

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