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