From 5160c7efa5771d74b560f9c2ea761f09e08a9216 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Bj=C3=B8rn=20Erik=20Pedersen?= Date: Thu, 19 Oct 2023 10:53:27 +0200 Subject: tpl/debug: Add debug.Timer Closes #11580 --- deps/deps.go | 9 +++- hugolib/hugo_sites_build.go | 18 ++++---- tpl/debug/debug.go | 95 ++++++++++++++++++++++++++++++++++++++++++- tpl/debug/integration_test.go | 45 ++++++++++++++++++++ 4 files changed, 157 insertions(+), 10 deletions(-) create mode 100644 tpl/debug/integration_test.go diff --git a/deps/deps.go b/deps/deps.go index 309555080..4d1812015 100644 --- a/deps/deps.go +++ b/deps/deps.go @@ -33,7 +33,6 @@ import ( // There will be normally only one instance of deps in play // at a given time, i.e. one per Site built. type Deps struct { - // The logger to use. Log loggers.Logger `json:"-"` @@ -77,6 +76,9 @@ type Deps struct { // BuildStartListeners will be notified before a build starts. BuildStartListeners *Listeners + // BuildEndListeners will be notified after a build finishes. + BuildEndListeners *Listeners + // Resources that gets closed when the build is done or the server shuts down. BuildClosers *Closers @@ -97,7 +99,6 @@ func (d Deps) Clone(s page.Site, conf config.AllProvider) (*Deps, error) { } return &d, nil - } func (d *Deps) SetTempl(t *tpl.TemplateHandlers) { @@ -132,6 +133,10 @@ func (d *Deps) Init() error { d.BuildStartListeners = &Listeners{} } + if d.BuildEndListeners == nil { + d.BuildEndListeners = &Listeners{} + } + if d.BuildClosers == nil { d.BuildClosers = &Closers{} } diff --git a/hugolib/hugo_sites_build.go b/hugolib/hugo_sites_build.go index 167d19eb5..27fde5822 100644 --- a/hugolib/hugo_sites_build.go +++ b/hugolib/hugo_sites_build.go @@ -17,6 +17,7 @@ import ( "bytes" "context" "encoding/json" + "errors" "fmt" "path/filepath" "strings" @@ -38,8 +39,6 @@ import ( "github.com/gohugoio/hugo/output" - "errors" - "github.com/fsnotify/fsnotify" "github.com/gohugoio/hugo/helpers" ) @@ -68,6 +67,12 @@ func (h *HugoSites) Build(config BuildCfg, events ...fsnotify.Event) error { defer unlock() } + defer func() { + for _, s := range h.Sites { + s.Deps.BuildEndListeners.Notify() + } + }() + infol := h.Log.InfoCommand("build") errCollector := h.StartErrorCollector() @@ -344,7 +349,6 @@ func (h *HugoSites) postRenderOnce() error { h.Log.Warnf("Template %s is unused, source file %s", unusedTemplate.Name(), unusedTemplate.Filename()) } } - }) return nil } @@ -384,7 +388,7 @@ func (h *HugoSites) postProcess(l logg.LevelLogger) error { } // Make sure it's written to the OS fs as this is used by // editors. - if err := afero.WriteFile(hugofs.Os, filename, b, 0666); err != nil { + if err := afero.WriteFile(hugofs.Os, filename, b, 0o666); err != nil { h.Log.Warnf("Failed to write jsconfig.json: %s", err) } } @@ -446,7 +450,7 @@ func (h *HugoSites) postProcess(l logg.LevelLogger) error { } if changed { - return afero.WriteFile(h.BaseFs.PublishFs, filename, content, 0666) + return afero.WriteFile(h.BaseFs.PublishFs, filename, content, 0o666) } return nil @@ -512,13 +516,13 @@ func (h *HugoSites) writeBuildStats() error { } // Make sure it's always written to the OS fs. - if err := afero.WriteFile(hugofs.Os, filename, js, 0666); err != nil { + if err := afero.WriteFile(hugofs.Os, filename, js, 0o666); err != nil { return err } // Write to the destination as well if it's a in-memory fs. if !hugofs.IsOsFs(h.Fs.Source) { - if err := afero.WriteFile(h.Fs.WorkingDirWritable, filename, js, 0666); err != nil { + if err := afero.WriteFile(h.Fs.WorkingDirWritable, filename, js, 0o666); err != nil { return err } } diff --git a/tpl/debug/debug.go b/tpl/debug/debug.go index d07a2804e..02fe562c3 100644 --- a/tpl/debug/debug.go +++ b/tpl/debug/debug.go @@ -15,6 +15,11 @@ package debug import ( + "sort" + "sync" + "time" + + "github.com/bep/logg" "github.com/sanity-io/litter" "github.com/spf13/cast" "github.com/yuin/goldmark/util" @@ -24,11 +29,58 @@ import ( // New returns a new instance of the debug-namespaced template functions. func New(d *deps.Deps) *Namespace { - return &Namespace{} + var timers map[string][]*timer + if d.Log.Level() <= logg.LevelInfo { + timers = make(map[string][]*timer) + } + ns := &Namespace{ + timers: timers, + } + + if ns.timers == nil { + return ns + } + + l := d.Log.InfoCommand("timer") + + d.BuildEndListeners.Add(func() { + type nameCountDuration struct { + Name string + Count int + Duration time.Duration + } + + var timersSorted []nameCountDuration + + for k, v := range timers { + var total time.Duration + for _, t := range v { + // Stop any running timers. + t.Stop() + total += t.elapsed + } + timersSorted = append(timersSorted, nameCountDuration{k, len(v), total}) + } + + sort.Slice(timersSorted, func(i, j int) bool { + // Sort it so the slowest gets printed last. + return timersSorted[i].Duration < timersSorted[j].Duration + }) + + for _, t := range timersSorted { + l.WithField("name", t.Name).WithField("count", t.Count).WithField("duration", t.Duration).Logf("") + } + + ns.timers = make(map[string][]*timer) + }) + + return ns } // Namespace provides template functions for the "debug" namespace. type Namespace struct { + timersMu sync.Mutex + timers map[string][]*timer } // Dump returns a object dump of val as a string. @@ -49,3 +101,44 @@ func (ns *Namespace) VisualizeSpaces(val any) string { s := cast.ToString(val) return string(util.VisualizeSpaces([]byte(s))) } + +func (ns *Namespace) Timer(name string) Timer { + if ns.timers == nil { + return nopTimer + } + ns.timersMu.Lock() + defer ns.timersMu.Unlock() + t := &timer{start: time.Now()} + ns.timers[name] = append(ns.timers[name], t) + return t +} + +var nopTimer = nopTimerImpl{} + +type nopTimerImpl struct{} + +func (nopTimerImpl) Stop() string { + return "" +} + +// Timer is a timer that can be stopped. +type Timer interface { + // Stop stops the timer and returns an empty string. + // Stop can be called multiple times, but only the first call will stop the timer. + // If Stop is not called, the timer will be stopped when the build ends. + Stop() string +} + +type timer struct { + start time.Time + elapsed time.Duration + stopOnce sync.Once +} + +func (t *timer) Stop() string { + t.stopOnce.Do(func() { + t.elapsed = time.Since(t.start) + }) + // This is used in templates, we need to return something. + return "" +} diff --git a/tpl/debug/integration_test.go b/tpl/debug/integration_test.go new file mode 100644 index 000000000..6520e60fb --- /dev/null +++ b/tpl/debug/integration_test.go @@ -0,0 +1,45 @@ +// Copyright 2023 The Hugo Authors. All rights reserved. +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless requiredF by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +package debug_test + +import ( + "testing" + + "github.com/bep/logg" + "github.com/gohugoio/hugo/hugolib" +) + +func TestTimer(t *testing.T) { + files := ` +-- hugo.toml -- +baseURL = "https://example.org/" +disableKinds = ["taxonomy", "term"] +-- layouts/index.html -- +{{ range seq 2 }} +{{ $t := debug.Timer "foo" }} +{{ seq 1 1000 }} +{{ $t.Stop }} +{{ end }} + +` + b := hugolib.NewIntegrationTestBuilder( + hugolib.IntegrationTestConfig{ + T: t, + TxtarString: files, + LogLevel: logg.LevelInfo, + }, + ).Build() + + b.AssertLogContains("imer: name \"foo\" count '\\x02' duration") +} -- cgit v1.2.3