tpl/partials: Make sure a cached partial is invoked only once

This commit revises the locking strategy for `partialCached`. We have added a benchmark that may be a little artificial, but it should at least show that we're not losing any performance over this:

```bash
name              old time/op    new time/op    delta
IncludeCached-10    12.2ms ± 2%    11.3ms ± 1%   -7.36%  (p=0.029 n=4+4)

name              old alloc/op   new alloc/op   delta
IncludeCached-10    7.17MB ± 0%    5.09MB ± 0%  -29.00%  (p=0.029 n=4+4)

name              old allocs/op  new allocs/op  delta
IncludeCached-10      128k ± 1%       70k ± 0%  -45.42%  (p=0.029 n=4+4)
```

This commit also revises the template metrics hints logic a little, and add a test for it, which output is currently this:

```bash
 cumulative       average       maximum      cache  percent  cached  total
       duration      duration      duration  potential   cached   count  count  template
     ----------      --------      --------  ---------  -------  ------  -----  --------
      163.334µs     163.334µs     163.334µs          0        0       0      1  index.html
       23.749µs       5.937µs      19.916µs         25       50       2      4  partials/dynamic1.html
        9.625µs       4.812µs        6.75µs        100       50       1      2  partials/static1.html
        7.625µs       7.625µs       7.625µs        100        0       0      1  partials/static2.html
```

Some notes:

* The duration now includes the cached invocations (which should be very short)
* A cached template gets executed once before it gets cached, so the "percent cached" will never be 100.

Fixes #4086
Fixes #9506
This commit is contained in:
Bjørn Erik Pedersen 2022-02-16 10:26:42 +01:00
parent 26a5e89faa
commit 0927cf739f
6 changed files with 171 additions and 14 deletions

View file

@ -63,7 +63,7 @@ type stringChecker struct {
argNames argNames
} }
// Check implements Checker.Check by checking that got and args[0] represents the same normalized text (whitespace etc. trimmed). // Check implements Checker.Check by checking that got and args[0] represents the same normalized text (whitespace etc. removed).
func (c *stringChecker) Check(got interface{}, args []interface{}, note func(key string, value interface{})) (err error) { func (c *stringChecker) Check(got interface{}, args []interface{}, note func(key string, value interface{})) (err error) {
s1, s2 := cast.ToString(got), cast.ToString(args[0]) s1, s2 := cast.ToString(got), cast.ToString(args[0])
@ -81,11 +81,12 @@ func (c *stringChecker) Check(got interface{}, args []interface{}, note func(key
} }
func normalizeString(s string) string { func normalizeString(s string) string {
s = strings.ReplaceAll(s, "\r\n", "\n")
lines := strings.Split(strings.TrimSpace(s), "\n") lines := strings.Split(strings.TrimSpace(s), "\n")
for i, line := range lines { for i, line := range lines {
lines[i] = strings.TrimSpace(line) lines[i] = strings.Join(strings.Fields(strings.TrimSpace(line)), "")
} }
return strings.Join(lines, "\n") return strings.Join(lines, "\n")
} }

View file

@ -17,6 +17,7 @@ package math
import ( import (
"errors" "errors"
"math" "math"
"sync/atomic"
_math "github.com/gohugoio/hugo/common/math" _math "github.com/gohugoio/hugo/common/math"
@ -162,3 +163,14 @@ func (ns *Namespace) Sqrt(a interface{}) (float64, error) {
func (ns *Namespace) Sub(a, b interface{}) (interface{}, error) { func (ns *Namespace) Sub(a, b interface{}) (interface{}, error) {
return _math.DoArithmetic(a, b, '-') return _math.DoArithmetic(a, b, '-')
} }
var counter uint64
// Counter increments and returns a global counter.
// This was originally added to be used in tests where now.UnixNano did not
// have the needed precision (especially on Windows).
// Note that given the parallel nature of Hugo, you cannot use this to get sequences of numbers,
// and the counter will reset on new builds.
func (ns *Namespace) Counter() uint64 {
return atomic.AddUint64(&counter, uint64(1))
}

View file

@ -18,14 +18,14 @@ import (
"github.com/gohugoio/hugo/tpl/internal" "github.com/gohugoio/hugo/tpl/internal"
) )
const name = "partials" const namespaceName = "partials"
func init() { func init() {
f := func(d *deps.Deps) *internal.TemplateFuncsNamespace { f := func(d *deps.Deps) *internal.TemplateFuncsNamespace {
ctx := New(d) ctx := New(d)
ns := &internal.TemplateFuncsNamespace{ ns := &internal.TemplateFuncsNamespace{
Name: name, Name: namespaceName,
Context: func(args ...interface{}) (interface{}, error) { return ctx, nil }, Context: func(args ...interface{}) (interface{}, error) { return ctx, nil },
} }

View file

@ -33,7 +33,7 @@ func TestInit(t *testing.T) {
BuildStartListeners: &deps.Listeners{}, BuildStartListeners: &deps.Listeners{},
Log: loggers.NewErrorLogger(), Log: loggers.NewErrorLogger(),
}) })
if ns.Name == name { if ns.Name == namespaceName {
found = true found = true
break break
} }

View file

@ -14,8 +14,14 @@
package partials_test package partials_test
import ( import (
"bytes"
"fmt"
"regexp"
"sort"
"strings"
"testing" "testing"
"github.com/gohugoio/hugo/htesting/hqt"
"github.com/gohugoio/hugo/hugolib" "github.com/gohugoio/hugo/hugolib"
) )
@ -68,3 +74,128 @@ partialCached: foo
partialCached: foo partialCached: foo
`) `)
} }
func TestIncludeCacheHints(t *testing.T) {
t.Parallel()
files := `
-- config.toml --
baseURL = 'http://example.com/'
templateMetrics=true
templateMetricsHints=true
disableKinds = ["page", "section", "taxonomy", "term", "sitemap"]
[outputs]
home = ["HTML"]
-- layouts/index.html --
{{ partials.IncludeCached "static1.html" . }}
{{ partials.IncludeCached "static1.html" . }}
{{ partials.Include "static2.html" . }}
D1I: {{ partials.Include "dynamic1.html" . }}
D1C: {{ partials.IncludeCached "dynamic1.html" . }}
D1C: {{ partials.IncludeCached "dynamic1.html" . }}
D1C: {{ partials.IncludeCached "dynamic1.html" . }}
H1I: {{ partials.Include "halfdynamic1.html" . }}
H1C: {{ partials.IncludeCached "halfdynamic1.html" . }}
H1C: {{ partials.IncludeCached "halfdynamic1.html" . }}
-- layouts/partials/static1.html --
P1
-- layouts/partials/static2.html --
P2
-- layouts/partials/dynamic1.html --
{{ math.Counter }}
-- layouts/partials/halfdynamic1.html --
D1
{{ math.Counter }}
`
b := hugolib.NewIntegrationTestBuilder(
hugolib.IntegrationTestConfig{
T: t,
TxtarString: files,
},
).Build()
// fmt.Println(b.FileContent("public/index.html"))
var buf bytes.Buffer
b.H.Metrics.WriteMetrics(&buf)
got := buf.String()
// Get rid of all the durations, they are never the same.
durationRe := regexp.MustCompile(`\b[\.\d]*(ms|µs|s)\b`)
normalize := func(s string) string {
s = durationRe.ReplaceAllString(s, "")
linesIn := strings.Split(s, "\n")[3:]
var lines []string
for _, l := range linesIn {
l = strings.TrimSpace(l)
if l == "" {
continue
}
lines = append(lines, l)
}
sort.Strings(lines)
return strings.Join(lines, "\n")
}
got = normalize(got)
expect := `
0 0 0 1 index.html
100 0 0 1 partials/static2.html
100 50 1 2 partials/static1.html
25 50 2 4 partials/dynamic1.html
66 33 1 3 partials/halfdynamic1.html
`
b.Assert(got, hqt.IsSameString, expect)
}
// gobench --package ./tpl/partials
func BenchmarkIncludeCached(b *testing.B) {
files := `
-- config.toml --
baseURL = 'http://example.com/'
-- layouts/index.html --
-- layouts/_default/single.html --
{{ partialCached "heavy.html" "foo" }}
-- layouts/partials/heavy.html --
{{ $result := slice }}
{{ range site.RegularPages }}
{{ $result = $result | append (dict "title" .Title "link" .RelPermalink "readingTime" .ReadingTime) }}
{{ end }}
{{ range $result }}
* {{ .title }} {{ .link }} {{ .readingTime }}
{{ end }}
`
for i := 1; i < 100; i++ {
files += fmt.Sprintf("\n-- content/p%d.md --\n---\ntitle: page\n---\n"+strings.Repeat("FOO ", i), i)
}
cfg := hugolib.IntegrationTestConfig{
T: b,
TxtarString: files,
}
builders := make([]*hugolib.IntegrationTestBuilder, b.N)
for i, _ := range builders {
builders[i] = hugolib.NewIntegrationTestBuilder(cfg)
}
b.ResetTimer()
for i := 0; i < b.N; i++ {
builders[i].Build()
}
}

View file

@ -24,6 +24,7 @@ import (
"reflect" "reflect"
"strings" "strings"
"sync" "sync"
"time"
texttemplate "github.com/gohugoio/hugo/tpl/internal/go_templates/texttemplate" texttemplate "github.com/gohugoio/hugo/tpl/internal/go_templates/texttemplate"
@ -44,6 +45,13 @@ type partialCacheKey struct {
variant interface{} variant interface{}
} }
func (k partialCacheKey) templateName() string {
if !strings.HasPrefix(k.name, "partials/") {
return "partials/" + k.name
}
return k.name
}
// partialCache represents a cache of partials protected by a mutex. // partialCache represents a cache of partials protected by a mutex.
type partialCache struct { type partialCache struct {
sync.RWMutex sync.RWMutex
@ -211,6 +219,7 @@ func createKey(name string, variants ...interface{}) (partialCacheKey, error) {
var errUnHashable = errors.New("unhashable") var errUnHashable = errors.New("unhashable")
func (ns *Namespace) getOrCreate(key partialCacheKey, context interface{}) (result interface{}, err error) { func (ns *Namespace) getOrCreate(key partialCacheKey, context interface{}) (result interface{}, err error) {
start := time.Now()
defer func() { defer func() {
if r := recover(); r != nil { if r := recover(); r != nil {
err = r.(error) err = r.(error)
@ -226,9 +235,20 @@ func (ns *Namespace) getOrCreate(key partialCacheKey, context interface{}) (resu
ns.cachedPartials.RUnlock() ns.cachedPartials.RUnlock()
if ok { if ok {
if ns.deps.Metrics != nil {
ns.deps.Metrics.TrackValue(key.templateName(), p, true)
// The templates that gets executed is measued in Execute.
// We need to track the time spent in the cache to
// get the totals correct.
ns.deps.Metrics.MeasureSince(key.templateName(), start)
}
return p, nil return p, nil
} }
ns.cachedPartials.Lock()
defer ns.cachedPartials.Unlock()
var name string var name string
name, p, err = ns.include(key.name, context) name, p, err = ns.include(key.name, context)
if err != nil { if err != nil {
@ -236,14 +256,7 @@ func (ns *Namespace) getOrCreate(key partialCacheKey, context interface{}) (resu
} }
if ns.deps.Metrics != nil { if ns.deps.Metrics != nil {
ns.deps.Metrics.TrackValue(name, p, true) ns.deps.Metrics.TrackValue(name, p, false)
}
ns.cachedPartials.Lock()
defer ns.cachedPartials.Unlock()
// Double-check.
if p2, ok := ns.cachedPartials.p[key]; ok {
return p2, nil
} }
ns.cachedPartials.p[key] = p ns.cachedPartials.p[key] = p