tpl/debug: Add debug.Timer

Closes #11580

4 files changed, 157 insertions, 10 deletions

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")
+}