tpl/debug: Add debug.Timer

Closes #11580
This commit is contained in:
Bjørn Erik Pedersen 2023-10-19 10:53:27 +02:00
parent e2dd4cd05f
commit 5160c7efa5
4 changed files with 157 additions and 10 deletions

9
deps/deps.go vendored
View file

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

View file

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

View file

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

View file

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