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

Author: bep

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

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

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

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
 		}

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

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,24 +235,28 @@ 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 {
 		return nil, err
 	}
 
 	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