Add Build Performance page under "Troubleshooting"`

[rdwatters]

Per recommendation from @moorereason in Hugo forums here:

https://discuss.gohugo.io/t/new-docs-site-need-feedback/5765/7

Should call attention to the following:

• --verbose
• --stepAnalysis
• --renderToMemory
• partialCached function

[rdwatters]

@digitalcraftsman I could really use your help on this one whenever you have a minute:)

[moorereason]

This repo may end up being a great case study to walk through. 😜

$ hugo --stepAnalysis --renderToMemory
Started building sites ...
Go initialization:
        258.265545ms (259.985277ms)       249.18 MB     114624 Allocs
initialize:
        325.205µs (261.150696ms)            0.17 MB     278 Allocs
load data:
        10.111382ms (272.069703ms)          1.63 MB     44834 Allocs
load i18n:
        771ns (272.938201ms)        0.00 MB     0 Allocs
read pages from source:
        80.477733ms (353.961149ms)         11.45 MB     109526 Allocs
convert source:
        89.310451ms (443.735408ms)         19.71 MB     164754 Allocs
build Site meta:
        3.768136ms (447.861593ms)           0.32 MB     12092 Allocs
prepare pages:
        100.851742ms (549.879453ms)        40.14 MB     130700 Allocs
render and write aliases:
        8.708986ms (559.015725ms)           0.90 MB     16792 Allocs
render and write pages:
        10.267170333s (10.827670946s)    1675.03 MB     37939564 Allocs
render and write Sitemap:
        21.80858ms (10.85142262s)           1.34 MB     35341 Allocs
render and write robots.txt:
        22.973µs (10.853822419s)            0.00 MB     8 Allocs
render and write 404:
        32.424698ms (10.888415839s)         2.83 MB     67274 Allocs
Built site for language en:
0 of 8 drafts rendered
0 future content
0 expired content
294 regular pages created
259 other pages created
2 non-page files copied
0 paginator pages created
242 tags created
total in 10631 ms

An advanced topic, but the benchmark command is very handy, as well. You can output CPU and memory pprof profiles that can be analyzed with go tool pprof.

$ hugo benchmark --cpuprofile=cpu.prof
$ go tool pprof `which hugo` cpu.prof
Entering interactive mode (type "help" for commands)
(pprof) top20 -cum
9.52s of 273.97s total ( 3.47%)
Dropped 895 nodes (cum <= 1.37s)
Showing top 20 nodes out of 185 (cum >= 229.11s)
      flat  flat%   sum%        cum   cum%
     0.02s 0.0073% 0.0073%    252.30s 92.09%  text/template.(*Template).Execute
     0.03s 0.011% 0.018%    252.30s 92.09%  text/template.(*Template).execute
     0.02s 0.0073% 0.026%    252.28s 92.08%  html/template.(*Template).Execute
     0.92s  0.34%  0.36%    252.26s 92.08%  text/template.(*state).walk
     0.59s  0.22%  0.58%    251.53s 91.81%  text/template.(*state).evalPipeline
     0.77s  0.28%  0.86%    251.47s 91.79%  text/template.(*state).evalCommand
     0.95s  0.35%  1.20%    250.49s 91.43%  text/template.(*state).evalCall
     0.21s 0.077%  1.28%    250.16s 91.31%  text/template.(*state).evalFunction
     0.69s  0.25%  1.53%    249.79s 91.17%  reflect.Value.Call
     4.60s  1.68%  3.21%    249.76s 91.16%  reflect.Value.call
     0.39s  0.14%  3.35%    248.52s 90.71%  runtime.call64
     0.02s 0.0073%  3.36%    246.71s 90.05%  github.com/spf13/hugo/tpl/tplimpl.(*GoHTMLTemplate).Partial
         0     0%  3.36%    246.70s 90.05%  github.com/spf13/hugo/tpl.(Template).Partial-fm
     0.02s 0.0073%  3.37%    246.62s 90.02%  github.com/spf13/hugo/tpl/tplimpl.(*GoHTMLTemplate).ExecuteTemplateToHTML
     0.01s 0.0037%  3.37%    246.31s 89.90%  github.com/spf13/hugo/tpl/tplimpl.(*GoHTMLTemplate).executeTemplate
     0.14s 0.051%  3.42%    241.23s 88.05%  text/template.(*state).walkIfOrWith
     0.05s 0.018%  3.44%    240.51s 87.79%  text/template.(*state).walkRange
     0.09s 0.033%  3.47%    240.11s 87.64%  text/template.(*state).walkRange.func1
         0     0%  3.47%    234.09s 85.44%  github.com/spf13/hugo/hugolib.(*Site).renderThing
         0     0%  3.47%    229.11s 83.63%  github.com/spf13/hugo/hugolib.(*Site).renderForLayouts

It looks like we spend a lot of time rendering partial templates. Two things to look into are using partialCached were possible (and considering the optional variant parameter) and trying to factor out expensive loops.

[rdwatters]

This repo may end up being a great case study to walk through.

Haha. It is. In fact, when you first put this on the forums, I used partialCached on site-navigation.html. I'm not running quite as slow as the above, but locally I'm getting about 3.3 seconds to build. When caching the partial, I was down to < 400 ms. So I'm going to assume that's the culprit. I'm pulling from a data file rather than using Hugo's built-in menus, which should probably change in the future for dogfooding reasons alone.

I also have the build set up for CRP, which is what makes our pagespeed scores so fantastic, although I've disabled it temporarily...I'm assuming this could be cached, but I don't think that's what's slowing this down. Note that style-embed.html is part of the Gulp build.