metrics: Add simple template metrics feature

commands/hugo.go

@@ -241,6 +241,7 @@ func initHugoBuildCommonFlags(cmd *cobra.Command) {
 	cmd.Flags().Bool("enableGitInfo", false, "add Git revision, date and author info to the pages")
 
 	cmd.Flags().BoolVar(&nitro.AnalysisOn, "stepAnalysis", false, "display memory and timing of different steps of the program")
+	cmd.Flags().Bool("templateMetrics", false, "display metrics about template executions")
 	cmd.Flags().Bool("pluralizeListTitles", true, "pluralize titles in lists using inflect")
 	cmd.Flags().Bool("preserveTaxonomyNames", false, `preserve taxonomy names as written ("Gérard Depardieu" vs "gerard-depardieu")`)
 	cmd.Flags().BoolP("forceSyncStatic", "", false, "copy all files when static is changed.")
@@ -475,6 +476,7 @@ func (c *commandeer) initializeFlags(cmd *cobra.Command) {
 		"forceSyncStatic",
 		"noTimes",
 		"noChmod",
+		"templateMetrics",
 	}
 
 	// Remove these in Hugo 0.23.

deps/deps.go

@@ -8,6 +8,7 @@ import (
 	"github.com/gohugoio/hugo/config"
 	"github.com/gohugoio/hugo/helpers"
 	"github.com/gohugoio/hugo/hugofs"
+	"github.com/gohugoio/hugo/metrics"
 	"github.com/gohugoio/hugo/output"
 	"github.com/gohugoio/hugo/tpl"
 	jww "github.com/spf13/jwalterweatherman"
@@ -47,6 +48,8 @@ type Deps struct {
 	WithTemplate     func(templ tpl.TemplateHandler) error `json:"-"`
 
 	translationProvider ResourceProvider
+
+	Metrics metrics.Provider
 }
 
 // ResourceProvider is used to create and refresh, and clone resources needed.
@@ -131,6 +134,10 @@ func New(cfg DepsCfg) (*Deps, error) {
 		Language:            cfg.Language,
 	}
 
+	if cfg.Cfg.GetBool("templateMetrics") {
+		d.Metrics = metrics.NewProvider()
+	}
+
 	return d, nil
 }
 

hugolib/hugo_sites_build.go

@@ -25,6 +25,10 @@ import (
 // Build builds all sites. If filesystem events are provided,
 // this is considered to be a potential partial rebuild.
 func (h *HugoSites) Build(config BuildCfg, events ...fsnotify.Event) error {
+	if h.Metrics != nil {
+		h.Metrics.Reset()
+	}
+
 	t0 := time.Now()
 
 	// Need a pointer as this may be modified.

hugolib/site.go

@@ -14,6 +14,7 @@
 package hugolib
 
 import (
+	"bytes"
 	"errors"
 	"fmt"
 	"html/template"
@@ -1730,6 +1731,16 @@ func (s *Site) appendThemeTemplates(in []string) []string {
 // Stats prints Hugo builds stats to the console.
 // This is what you see after a successful hugo build.
 func (s *Site) Stats() {
+	s.Log.FEEDBACK.Println()
+
+	if s.Cfg.GetBool("templateMetrics") {
+		var b bytes.Buffer
+		s.Metrics.WriteMetrics(&b)
+
+		s.Log.FEEDBACK.Printf("Template Metrics:\n\n")
+		s.Log.FEEDBACK.Print(b.String())
+		s.Log.FEEDBACK.Println()
+	}
 
 	s.Log.FEEDBACK.Printf("Built site for language %s:\n", s.Language.Lang)
 	s.Log.FEEDBACK.Println(s.draftStats())

metrics/metrics.go

@@ -0,0 +1,117 @@
+// Copyright 2017 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 metrics provides simple metrics tracking features.
+package metrics
+
+import (
+	"fmt"
+	"io"
+	"sort"
+	"sync"
+	"time"
+)
+
+// The Provider interface defines an interface for measuring metrics.
+type Provider interface {
+	// MeasureSince adds a measurement for key to the metric store.
+	// Used with defer and time.Now().
+	MeasureSince(key string, start time.Time)
+
+	// WriteMetrics will write a summary of the metrics to w.
+	WriteMetrics(w io.Writer)
+
+	// Reset clears the metric store.
+	Reset()
+}
+
+// Store provides storage for a set of metrics.
+type Store struct {
+	metrics map[string][]time.Duration
+	mu      *sync.Mutex
+}
+
+// NewProvider returns a new instance of a metric store.
+func NewProvider() Provider {
+	return &Store{
+		metrics: make(map[string][]time.Duration),
+		mu:      &sync.Mutex{},
+	}
+}
+
+// Reset clears the metrics store.
+func (s *Store) Reset() {
+	s.mu.Lock()
+	s.metrics = make(map[string][]time.Duration)
+	s.mu.Unlock()
+}
+
+// MeasureSince adds a measurement for key to the metric store.
+func (s *Store) MeasureSince(key string, start time.Time) {
+	s.mu.Lock()
+	s.metrics[key] = append(s.metrics[key], time.Since(start))
+	s.mu.Unlock()
+}
+
+// WriteMetrics writes a summary of the metrics to w.
+func (s *Store) WriteMetrics(w io.Writer) {
+	s.mu.Lock()
+
+	results := make([]result, len(s.metrics))
+
+	var i int
+	for k, v := range s.metrics {
+		var sum time.Duration
+		var max time.Duration
+
+		for _, d := range v {
+			sum += d
+			if d > max {
+				max = d
+			}
+		}
+
+		avg := time.Duration(int(sum) / len(v))
+
+		results[i] = result{key: k, count: len(v), max: max, sum: sum, avg: avg}
+		i++
+	}
+
+	s.mu.Unlock()
+
+	// sort and print results
+	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")
+	fmt.Fprintf(w, "  %13s  %12s  %12s  %5s  %s\n", "----------", "--------", "--------", "-----", "--------")
+
+	sort.Sort(bySum(results))
+	for _, v := range results {
+		fmt.Fprintf(w, "  %13s  %12s  %12s  %5d  %s\n", v.sum, v.avg, v.max, v.count, v.key)
+	}
+
+}
+
+// A result represents the calculated results for a given metric.
+type result struct {
+	key   string
+	count int
+	sum   time.Duration
+	max   time.Duration
+	avg   time.Duration
+}
+
+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 }

tpl/template.go

@@ -15,13 +15,15 @@ package tpl
 
 import (
 	"io"
+	"time"
 
 	"text/template/parse"
 
 	"html/template"
 	texttemplate "text/template"
 
 	bp "github.com/gohugoio/hugo/bufferpool"
+	"github.com/gohugoio/hugo/metrics"
 )
 
 var (
@@ -66,13 +68,16 @@ type TemplateDebugger interface {
 // TemplateAdapter implements the TemplateExecutor interface.
 type TemplateAdapter struct {
 	Template
+	Metrics metrics.Provider
 }
 
 // Execute executes the current template. The actual execution is performed
 // by the embedded text or html template, but we add an implementation here so
 // we can add a timer for some metrics.
 func (t *TemplateAdapter) Execute(w io.Writer, data interface{}) error {
-	// TODO(moorereason) metrics fmt.Println("Execute:", t.Name())
+	if t.Metrics != nil {
+		defer t.Metrics.MeasureSince(t.Name(), time.Now())
+	}
 	return t.Template.Execute(w, data)
 }
 

tpl/tplimpl/template.go

@@ -112,15 +112,25 @@ func (t *templateHandler) Lookup(name string) *tpl.TemplateAdapter {
 		// in the text template collection.
 		// The templates are stored without the prefix identificator.
 		name = strings.TrimPrefix(name, textTmplNamePrefix)
-		return t.text.Lookup(name)
+
+		te := t.text.Lookup(name)
+		if te != nil {
+			te.Metrics = t.Deps.Metrics
+		}
+		return te
 	}
 
 	// Look in both
 	if te := t.html.Lookup(name); te != nil {
+		te.Metrics = t.Deps.Metrics
 		return te
 	}
 
-	return t.text.Lookup(name)
+	te := t.text.Lookup(name)
+	if te != nil {
+		te.Metrics = t.Deps.Metrics
+	}
+	return te
 }
 
 func (t *templateHandler) clone(d *deps.Deps) *templateHandler {