tpl/debug: Add debug.Timer

Closes #11580

2 files changed, 139 insertions, 1 deletions

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