tpl/debug: Add debug.Timer - hugo - [fork] hugo port for 9front
(HTM) git clone git@git.drkhsh.at/hugo.git
(DIR) Log
(DIR) Files
(DIR) Refs
(DIR) Submodules
(DIR) README
(DIR) LICENSE
---
(DIR) commit 5160c7efa5771d74b560f9c2ea761f09e08a9216
(DIR) parent e2dd4cd05fa96a08d49b3b198edf0ccf9a94970e
(HTM) Author: Bjørn Erik Pedersen <bjorn.erik.pedersen@gmail.com>
Date: Thu, 19 Oct 2023 10:53:27 +0200
tpl/debug: Add debug.Timer
Closes #11580
Diffstat:
M deps/deps.go | 9 +++++++--
M hugolib/hugo_sites_build.go | 18 +++++++++++-------
M tpl/debug/debug.go | 95 ++++++++++++++++++++++++++++++-
A tpl/debug/integration_test.go | 45 +++++++++++++++++++++++++++++++
4 files changed, 157 insertions(+), 10 deletions(-)
---
(DIR) diff --git 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{}
}
(DIR) diff --git 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
}
}
(DIR) diff --git 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 ""
+}
(DIR) diff --git a/tpl/debug/integration_test.go 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")
+}