From 1ba7573fd8fe80a82dd4aaf2a5a9dc75243a69f1 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 +- metrics/metrics.go | 12 ++- tpl/partials/init.go | 4 +- tpl/partials/init_test.go | 2 +- tpl/partials/integration_test.go | 137 +++++++++++++++++++++++++++++++ tpl/partials/partials.go | 29 +++++-- 6 files changed, 174 insertions(+), 17 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/metrics/metrics.go b/metrics/metrics.go index 12f825e19dd..42aaa2e8e1f 100644 --- a/metrics/metrics.go +++ b/metrics/metrics.go @@ -201,9 +201,15 @@ type result struct { type bySum []result -func (b bySum) Len() int { return len(b) } -func (b bySum) Swap(i, j int) { b[i], b[j] = b[j], b[i] } -func (b bySum) Less(i, j int) bool { return b[i].sum > b[j].sum } +func (b bySum) Len() int { return len(b) } +func (b bySum) Swap(i, j int) { b[i], b[j] = b[j], b[i] } +func (b bySum) Less(i, j int) bool { + // Make the sort more stable for testing. + if b[i].sum.Milliseconds() == b[j].sum.Milliseconds() { + return b[i].key < b[j].key + } + return b[i].sum > b[j].sum +} // howSimilar is a naive diff implementation that returns // a number between 0-100 indicating how similar a and b are. 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..e935a3038f2 100644 --- a/tpl/partials/integration_test.go +++ b/tpl/partials/integration_test.go @@ -14,8 +14,13 @@ package partials_test import ( + "bytes" + "fmt" + "regexp" + "strings" "testing" + "github.com/gohugoio/hugo/htesting/hqt" "github.com/gohugoio/hugo/hugolib" ) @@ -68,3 +73,135 @@ 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" . }} + +Expext: Total count 4, cache count 2. +D1I: {{ partials.Include "dynamic1.html" . }} +D1C: {{ partials.IncludeCached "dynamic1.html" . }} +D1C: {{ partials.IncludeCached "dynamic1.html" . }} +D1C: {{ partials.IncludeCached "dynamic1.html" . }} + +-- layouts/partials/static1.html -- +P1 +-- layouts/partials/static2.html -- +P2 +-- layouts/partials/dynamic1.html -- +{{ now.UnixNano }} +-- layouts/partials/dynamic2.html -- +{{ now.UnixNano }} +-- layouts/partials/halfdynamic1.html -- +D1 +{{ now.UnixNano }} +-- layouts/partials/halfdynamic2.html -- +D2 +{{ now.UnixNano }} + + ` + + 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, "") + lines := strings.Split(s, "\n") + var result strings.Builder + for i, l := range lines { + if i < 3 { + continue + } + l = strings.TrimSpace(l) + if l == "" { + continue + } + + result.WriteString(l + "\n") + } + + return result.String() + } + + fmt.Println("Got1:\n", got) + + got = normalize(got) + + fmt.Println("Got2:\n", got) + + expect := ` + 0 0 0 1 index.html + 25 50 2 4 partials/dynamic1.html + 100 50 1 2 partials/static1.html + 100 0 0 1 partials/static2.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