diff --git a/commands/hugo.go b/commands/hugo.go index 388f55db9..d2bf18c47 100644 --- a/commands/hugo.go +++ b/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. diff --git a/deps/deps.go b/deps/deps.go index d8ba3313e..0c610c9ba 100644 --- a/deps/deps.go +++ b/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 } diff --git a/hugolib/hugo_sites_build.go b/hugolib/hugo_sites_build.go index fa0eac702..f73989908 100644 --- a/hugolib/hugo_sites_build.go +++ b/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. diff --git a/hugolib/site.go b/hugolib/site.go index 39908d810..8e1090a31 100644 --- a/hugolib/site.go +++ b/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()) diff --git a/metrics/metrics.go b/metrics/metrics.go new file mode 100644 index 000000000..cabf52131 --- /dev/null +++ b/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 } diff --git a/tpl/template.go b/tpl/template.go index 7be496df9..bdb917ba9 100644 --- a/tpl/template.go +++ b/tpl/template.go @@ -15,6 +15,7 @@ package tpl import ( "io" + "time" "text/template/parse" @@ -22,6 +23,7 @@ import ( 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) } diff --git a/tpl/tplimpl/template.go b/tpl/tplimpl/template.go index a8417819e..f25ff8909 100644 --- a/tpl/tplimpl/template.go +++ b/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 {