From 0927cf739fee9646c7fb917965799d9acf080922 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Bj=C3=B8rn=20Erik=20Pedersen?= Date: Wed, 16 Feb 2022 10:26:42 +0100 Subject: [PATCH] tpl/partials: Make sure a cached partial is invoked only once MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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 --- htesting/hqt/checkers.go | 7 +- tpl/math/math.go | 12 +++ tpl/partials/init.go | 4 +- tpl/partials/init_test.go | 2 +- tpl/partials/integration_test.go | 131 +++++++++++++++++++++++++++++++ tpl/partials/partials.go | 29 +++++-- 6 files changed, 171 insertions(+), 14 deletions(-) diff --git a/htesting/hqt/checkers.go b/htesting/hqt/checkers.go index c12f78034cf..e518dfa1f8d 100644 --- a/htesting/hqt/checkers.go +++ b/htesting/hqt/checkers.go @@ -63,7 +63,7 @@ type stringChecker struct { 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) { 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 { + s = strings.ReplaceAll(s, "\r\n", "\n") + lines := strings.Split(strings.TrimSpace(s), "\n") for i, line := range lines { - lines[i] = strings.TrimSpace(line) + lines[i] = strings.Join(strings.Fields(strings.TrimSpace(line)), "") } - return strings.Join(lines, "\n") } diff --git a/tpl/math/math.go b/tpl/math/math.go index d70a3f8332f..cd4a47ecad3 100644 --- a/tpl/math/math.go +++ b/tpl/math/math.go @@ -17,6 +17,7 @@ package math import ( "errors" "math" + "sync/atomic" _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) { 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)) +} diff --git a/tpl/partials/init.go b/tpl/partials/init.go index d6670d99eaa..1857b167a9e 100644 --- a/tpl/partials/init.go +++ b/tpl/partials/init.go @@ -18,14 +18,14 @@ import ( "github.com/gohugoio/hugo/tpl/internal" ) -const name = "partials" +const namespaceName = "partials" func init() { f := func(d *deps.Deps) *internal.TemplateFuncsNamespace { ctx := New(d) ns := &internal.TemplateFuncsNamespace{ - Name: name, + Name: namespaceName, Context: func(args ...interface{}) (interface{}, error) { return ctx, nil }, } diff --git a/tpl/partials/init_test.go b/tpl/partials/init_test.go index 467e202d414..b18ac0a00a8 100644 --- a/tpl/partials/init_test.go +++ b/tpl/partials/init_test.go @@ -33,7 +33,7 @@ func TestInit(t *testing.T) { BuildStartListeners: &deps.Listeners{}, Log: loggers.NewErrorLogger(), }) - if ns.Name == name { + if ns.Name == namespaceName { found = true break } diff --git a/tpl/partials/integration_test.go b/tpl/partials/integration_test.go index f462f35f5f5..9826ac119c0 100644 --- a/tpl/partials/integration_test.go +++ b/tpl/partials/integration_test.go @@ -14,8 +14,14 @@ package partials_test import ( + "bytes" + "fmt" + "regexp" + "sort" + "strings" "testing" + "github.com/gohugoio/hugo/htesting/hqt" "github.com/gohugoio/hugo/hugolib" ) @@ -68,3 +74,128 @@ 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() + } +} diff --git a/tpl/partials/partials.go b/tpl/partials/partials.go index d80ccfa4fa1..787b49ed376 100644 --- a/tpl/partials/partials.go +++ b/tpl/partials/partials.go @@ -24,6 +24,7 @@ import ( "reflect" "strings" "sync" + "time" texttemplate "github.com/gohugoio/hugo/tpl/internal/go_templates/texttemplate" @@ -44,6 +45,13 @@ type partialCacheKey struct { 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. type partialCache struct { sync.RWMutex @@ -211,6 +219,7 @@ func createKey(name string, variants ...interface{}) (partialCacheKey, error) { var errUnHashable = errors.New("unhashable") func (ns *Namespace) getOrCreate(key partialCacheKey, context interface{}) (result interface{}, err error) { + start := time.Now() defer func() { if r := recover(); r != nil { err = r.(error) @@ -226,9 +235,20 @@ func (ns *Namespace) getOrCreate(key partialCacheKey, context interface{}) (resu ns.cachedPartials.RUnlock() 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 } + ns.cachedPartials.Lock() + defer ns.cachedPartials.Unlock() + var name string name, p, err = ns.include(key.name, context) if err != nil { @@ -236,14 +256,7 @@ func (ns *Namespace) getOrCreate(key partialCacheKey, context interface{}) (resu } if ns.deps.Metrics != nil { - ns.deps.Metrics.TrackValue(name, p, true) - } - - ns.cachedPartials.Lock() - defer ns.cachedPartials.Unlock() - // Double-check. - if p2, ok := ns.cachedPartials.p[key]; ok { - return p2, nil + ns.deps.Metrics.TrackValue(name, p, false) } ns.cachedPartials.p[key] = p