metrics: Add cached count tracking

Track cached partial executions and display more useful info when
showing the hints output. Also group cache hints and counters together
to the right of the timing measurements.

Sample output:

     cumulative       average       maximum      cache  percent  cached  total
       duration      duration      duration  potential   cached   count  count  template
     ----------      --------      --------  ---------  -------  ------  -----  --------
       2.6973ms     674.325µs       857.3µs          0        0       0      4  _internal/_default/rss.xml
       2.6295ms     657.375µs       861.3µs          0        0       0      4  _default/single.html
       1.2563ms     314.075µs       381.5µs          0        0       0      4  news/single.html
        799.2µs       399.6µs       573.3µs          0        0       0      2  _internal/_default/sitemap.xml
        667.3µs       66.73µs       238.6µs         84        0       0     10  partials/header.html
        656.7µs      328.35µs       459.4µs          0        0       0      2  _default/list.html
        479.7µs       47.97µs         158µs         92        0       0     10  partials/head.html
        323.3µs       323.3µs       323.3µs          0        0       0      1  _internal/alias.html
        200.7µs       200.7µs       200.7µs          0        0       0      1  _internal/_default/sitemapindex.xml
         36.1µs       6.016µs        32.6µs        100       33       2      6  partials/footer.html
         27.4µs        13.7µs        26.7µs          0        0       0      2  index.html

Fixes #8375

metrics/metrics.go

@@ -25,11 +25,9 @@ import (
 	"sync"
 	"time"
 
-	"github.com/gohugoio/hugo/helpers"
-
 	"github.com/gohugoio/hugo/common/types"
-
 	"github.com/gohugoio/hugo/compare"
+	"github.com/gohugoio/hugo/helpers"
 )
 
 // The Provider interface defines an interface for measuring metrics.
@@ -42,7 +40,7 @@ type Provider interface {
 	WriteMetrics(w io.Writer)
 
 	// TrackValue tracks the value for diff calculations etc.
-	TrackValue(key string, value interface{})
+	TrackValue(key string, value interface{}, cached bool)
 
 	// Reset clears the metric store.
 	Reset()
@@ -54,8 +52,6 @@ type diff struct {
 	simSum   int
 }
 
-var counter = 0
-
 func (d *diff) add(v interface{}) *diff {
 	if types.IsNil(d.baseline) {
 		d.baseline = v
@@ -77,6 +73,8 @@ type Store struct {
 	mu             sync.Mutex
 	diffs          map[string]*diff
 	diffmu         sync.Mutex
+	cached         map[string]int
+	cachedmu       sync.Mutex
 }
 
 // NewProvider returns a new instance of a metric store.
@@ -85,6 +83,7 @@ func NewProvider(calculateHints bool) Provider {
 		calculateHints: calculateHints,
 		metrics:        make(map[string][]time.Duration),
 		diffs:          make(map[string]*diff),
+		cached:         make(map[string]int),
 	}
 }
 
@@ -93,24 +92,24 @@ func (s *Store) Reset() {
 	s.mu.Lock()
 	s.metrics = make(map[string][]time.Duration)
 	s.mu.Unlock()
+
 	s.diffmu.Lock()
 	s.diffs = make(map[string]*diff)
 	s.diffmu.Unlock()
+
+	s.cachedmu.Lock()
+	s.cached = make(map[string]int)
+	s.cachedmu.Unlock()
 }
 
 // TrackValue tracks the value for diff calculations etc.
-func (s *Store) TrackValue(key string, value interface{}) {
+func (s *Store) TrackValue(key string, value interface{}, cached bool) {
 	if !s.calculateHints {
 		return
 	}
 
 	s.diffmu.Lock()
-	var (
-		d     *diff
-		found bool
-	)
-
-	d, found = s.diffs[key]
+	d, found := s.diffs[key]
 
 	if !found {
 		d = &diff{}
@@ -118,8 +117,13 @@ func (s *Store) TrackValue(key string, value interface{}) {
 	}
 
 	d.add(value)
-
 	s.diffmu.Unlock()
+
+	if cached {
+		s.cachedmu.Lock()
+		s.cached[key] = s.cached[key] + 1
+		s.cachedmu.Unlock()
+	}
 }
 
 // MeasureSince adds a measurement for key to the metric store.
@@ -155,17 +159,18 @@ func (s *Store) WriteMetrics(w io.Writer) {
 		}
 
 		avg := time.Duration(int(sum) / len(v))
+		cacheCount := s.cached[k]
 
-		results[i] = result{key: k, count: len(v), max: max, sum: sum, avg: avg, cacheFactor: cacheFactor}
+		results[i] = result{key: k, count: len(v), max: max, sum: sum, avg: avg, cacheCount: cacheCount, cacheFactor: cacheFactor}
 		i++
 	}
 
 	s.mu.Unlock()
 
 	if s.calculateHints {
-		fmt.Fprintf(w, "  %9s  %13s  %12s  %12s  %5s  %s\n", "cache", "cumulative", "average", "maximum", "", "")
-		fmt.Fprintf(w, "  %9s  %13s  %12s  %12s  %5s  %s\n", "potential", "duration", "duration", "duration", "count", "template")
-		fmt.Fprintf(w, "  %9s  %13s  %12s  %12s  %5s  %s\n", "-----", "----------", "--------", "--------", "-----", "--------")
+		fmt.Fprintf(w, "  %13s  %12s  %12s  %9s  %7s  %6s  %5s  %s\n", "cumulative", "average", "maximum", "cache", "percent", "cached", "total", "")
+		fmt.Fprintf(w, "  %13s  %12s  %12s  %9s  %7s  %6s  %5s  %s\n", "duration", "duration", "duration", "potential", "cached", "count", "count", "template")
+		fmt.Fprintf(w, "  %13s  %12s  %12s  %9s  %7s  %6s  %5s  %s\n", "----------", "--------", "--------", "---------", "-------", "------", "-----", "--------")
 	} else {
 		fmt.Fprintf(w, "  %13s  %12s  %12s  %5s  %s\n", "cumulative", "average", "maximum", "", "")
 		fmt.Fprintf(w, "  %13s  %12s  %12s  %5s  %s\n", "duration", "duration", "duration", "count", "template")
@@ -176,7 +181,7 @@ func (s *Store) WriteMetrics(w io.Writer) {
 	sort.Sort(bySum(results))
 	for _, v := range results {
 		if s.calculateHints {
-			fmt.Fprintf(w, "  %9d %13s  %12s  %12s  %5d  %s\n", v.cacheFactor, v.sum, v.avg, v.max, v.count, v.key)
+			fmt.Fprintf(w, "  %13s  %12s  %12s  %9d  %7.f  %6d  %5d  %s\n", v.sum, v.avg, v.max, v.cacheFactor, float64(v.cacheCount)/float64(v.count)*100, v.cacheCount, v.count, v.key)
 		} else {
 			fmt.Fprintf(w, "  %13s  %12s  %12s  %5d  %s\n", v.sum, v.avg, v.max, v.count, v.key)
 		}
@@ -187,6 +192,7 @@ func (s *Store) WriteMetrics(w io.Writer) {
 type result struct {
 	key         string
 	count       int
+	cacheCount  int
 	cacheFactor int
 	sum         time.Duration
 	max         time.Duration

tpl/partials/integration_test.go

@@ -0,0 +1,70 @@
+// Copyright 2022 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 required 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 partials_test
+
+import (
+	"testing"
+
+	"github.com/gohugoio/hugo/hugolib"
+)
+
+func TestInclude(t *testing.T) {
+	t.Parallel()
+
+	files := `
+-- config.toml --
+baseURL = 'http://example.com/'
+-- layouts/index.html --
+partial: {{ partials.Include "foo.html" . }}
+-- layouts/partials/foo.html --
+foo
+  `
+
+	b := hugolib.NewIntegrationTestBuilder(
+		hugolib.IntegrationTestConfig{
+			T:           t,
+			TxtarString: files,
+		},
+	).Build()
+
+	b.AssertFileContent("public/index.html", `
+partial: foo
+`)
+}
+
+func TestIncludeCached(t *testing.T) {
+	t.Parallel()
+
+	files := `
+-- config.toml --
+baseURL = 'http://example.com/'
+-- layouts/index.html --
+partialCached: {{ partials.IncludeCached "foo.html" . }}
+partialCached: {{ partials.IncludeCached "foo.html" . }}
+-- layouts/partials/foo.html --
+foo
+  `
+
+	b := hugolib.NewIntegrationTestBuilder(
+		hugolib.IntegrationTestConfig{
+			T:           t,
+			TxtarString: files,
+		},
+	).Build()
+
+	b.AssertFileContent("public/index.html", `
+partialCached: foo
+partialCached: foo
+`)
+}

tpl/partials/partials.go

@@ -93,23 +93,41 @@ func (c *contextWrapper) Set(in interface{}) string {
 // Else, the rendered output will be returned:
 // A string if the partial is a text/template, or template.HTML when html/template.
 func (ns *Namespace) Include(name string, contextList ...interface{}) (interface{}, error) {
-	name = strings.TrimPrefix(name, "partials/")
+	name, result, err := ns.include(name, contextList...)
+	if err != nil {
+		return result, err
+	}
 
+	if ns.deps.Metrics != nil {
+		ns.deps.Metrics.TrackValue(name, result, false)
+	}
+
+	return result, nil
+}
+
+// include is a helper function that lookups and executes the named partial.
+// Returns the final template name and the rendered output.
+func (ns *Namespace) include(name string, contextList ...interface{}) (string, interface{}, error) {
 	var context interface{}
 	if len(contextList) > 0 {
 		context = contextList[0]
 	}
 
-	n := "partials/" + name
-	templ, found := ns.deps.Tmpl().Lookup(n)
+	var n string
+	if strings.HasPrefix(name, "partials/") {
+		n = name
+	} else {
+		n = "partials/" + name
+	}
 
+	templ, found := ns.deps.Tmpl().Lookup(n)
 	if !found {
 		// For legacy reasons.
 		templ, found = ns.deps.Tmpl().Lookup(n + ".html")
 	}
 
 	if !found {
-		return "", fmt.Errorf("partial %q not found", name)
+		return "", "", fmt.Errorf("partial %q not found", name)
 	}
 
 	var info tpl.ParseInfo
@@ -136,7 +154,7 @@ func (ns *Namespace) Include(name string, contextList ...interface{}) (interface
 	}
 
 	if err := ns.deps.Tmpl().Execute(templ, w, context); err != nil {
-		return "", err
+		return "", "", err
 	}
 
 	var result interface{}
@@ -149,11 +167,7 @@ func (ns *Namespace) Include(name string, contextList ...interface{}) (interface
 		result = template.HTML(w.(fmt.Stringer).String())
 	}
 
-	if ns.deps.Metrics != nil {
-		ns.deps.Metrics.TrackValue(templ.Name(), result)
-	}
-
-	return result, nil
+	return templ.Name(), result, nil
 }
 
 // IncludeCached executes and caches partial templates.  The cache is created with name+variants as the key.
@@ -215,11 +229,16 @@ func (ns *Namespace) getOrCreate(key partialCacheKey, context interface{}) (resu
 		return p, nil
 	}
 
-	p, err = ns.Include(key.name, context)
+	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.