Build performance analysis

[mattstratton]

Continuing the work @tgross did in devopsdays/devopsdays-theme#643

 ~/src/github.com/devopsdays/devopsdays-web  hugo --templateMetrics                                         
Building sites …
Template Metrics:

     cumulative       average       maximum
       duration      duration      duration  count  template
     ----------      --------      --------  -----  --------
  3m49.432171618s  1.865302208s  5.311868039s    123  program/single.html
  3m6.731520292s   76.123734ms  771.085511ms   2453  speaker/single.html
  2m23.784239797s    21.43474ms  2.014656398s   6708  partials/head.html
  2m19.133801538s   20.741473ms  2.013043683s   6708  partials/head/seo.html
  1m12.110467505s    10.74992ms  1.997155482s   6708  partials/head/seo/open_graph.html
  1m3.67344223s    9.492164ms  521.129238ms   6708  partials/head/seo/twitter_cards.html
  53.140918496s   22.077656ms  517.039327ms   2407  talk/single.html
  29.270577521s   21.649835ms  2.059329007s   1352  event/single.html
  17.104061504s    2.625335ms  235.159066ms   6515  partials/sponsors.html
  12.668118098s   94.538194ms  254.222729ms    134  speakers/single.html
   7.432626582s   43.980038ms  318.037132ms    169  welcome/single.html
     4.6995006s  111.892871ms  1.986306858s     42  partials/future.html
    3.06452896s     456.846µs   67.822828ms   6708  partials/head/seo/schema.html
    2.66170064s   95.060737ms  2.071359796s     28  blog/single.html
   2.477897896s  2.477897896s  2.477897896s      1  index.html
   2.367885892s     355.431µs   28.694785ms   6662  partials/events/event_navbar.html
   2.191751428s     326.736µs  222.915976ms   6708  partials/head_includes.html
   2.169926108s    6.027572ms   66.491105ms    360  shortcodes/event_logo.html
   2.092591884s  697.530628ms  2.047319712s      3  section/blog.html
   1.886484616s    8.815348ms   63.603751ms    214  partials/welcome.html
   1.592607329s  796.303664ms  1.587667801s      2  _internal/_default/rss.xml
   1.383603724s  345.900931ms   444.14626ms      4  events/single.html
   1.289453004s  322.363251ms  404.508424ms      4  partials/past.html
   1.203709852s     179.443µs   78.290849ms   6708  partials/footer_scripts.html
   861.364205ms     128.408µs  222.763552ms   6708  partials/google_analytics.html
   746.647443ms     111.307µs   14.845433ms   6708  partials/global_navbar.html
    232.31629ms      34.632µs    7.294997ms   6708  partials/meta.html
   219.721927ms     6.86631ms   37.732637ms     32  _default/single.html
   194.703726ms     452.799µs   12.428281ms    430  shortcodes/list_organizers.html
   159.591965ms  159.591965ms  159.591965ms      1  _internal/_default/sitemap.xml
    143.32661ms      57.886µs    2.564385ms   2476  shortcodes/event_link.html
   125.182722ms   41.727574ms   56.883483ms      3  partials/footer.html
    91.614068ms     213.055µs    2.972483ms    430  shortcodes/list_core.html
    76.071922ms      70.306µs     986.354µs   1082  shortcodes/email_organizers.html
     39.59023ms     105.856µs     1.28825ms    374  shortcodes/cfp_dates.html
    32.071408ms      90.088µs    1.942725ms    356  shortcodes/event_map.html
    29.869124ms     139.575µs    4.655992ms    214  partials/events/cta.html
     29.39512ms      57.188µs     403.019µs    514  shortcodes/event_start.html
    24.592537ms   24.592537ms   24.592537ms      1  speaking/single.html
    17.333237ms     619.044µs    5.636526ms     28  blog/summary.html
    17.164121ms      41.062µs     1.70338ms    418  shortcodes/event_twitter.html
    16.085653ms      38.667µs      411.26µs    416  shortcodes/event_location.html
    15.299321ms      33.998µs     362.402µs    450  shortcodes/event_end.html
    11.584282ms   11.584282ms   11.584282ms      1  section/events.rss.xml
    10.406871ms   10.406871ms   10.406871ms      1  partials/speaking.html
     9.846822ms    9.846822ms    9.846822ms      1  404.html
     9.361209ms    9.361209ms    9.361209ms      1  section/blog.rss.xml
     8.835478ms      42.478µs     217.587µs    208  shortcodes/email_proposals.html
     6.816844ms    6.816844ms    6.816844ms      1  partials/map.html
     6.108557ms    6.108557ms    6.108557ms      1  section/speaking.rss.xml
     1.504848ms     752.424µs     882.973µs      2  _internal/shortcodes/tweet.html
     1.273294ms     127.329µs     721.319µs     10  shortcodes/google_form.html
      888.301µs      148.05µs     324.027µs      6  _internal/shortcodes/figure.html
      757.348µs      75.734µs     284.565µs     10  shortcodes/registration_start.html
       699.41µs      69.941µs     566.871µs     10  shortcodes/emoji.html
      611.178µs      61.117µs     224.734µs     10  shortcodes/registration_end.html
      444.084µs     222.042µs     434.357µs      2  shortcodes/privacy_policy.html
      394.784µs      98.696µs     342.492µs      4  _internal/shortcodes/param.html
      377.309µs     188.654µs     277.233µs      2  _internal/shortcodes/youtube.html
      329.932µs     109.977µs     188.223µs      3  partials/blog_pagination.html
      138.873µs      46.291µs     136.586µs      3  _default/list.html

So yeah, that program page, wut.

Although the partials/head stuff has gotten much worse somehow. This is what it looked like a year ago:

16.358431432s     4.27113ms   39.009423ms   3830  partials/head.html

So building the head for the pages used to take a total of 16 seconds, and now it takes over 2 minutes. Hmm.

[mattstratton]

FWIW, this is the change that seemed to make partials/head take much longer: devopsdays/devopsdays-theme@f3e3487

All that was was REMOVING the og:updated_time from headers. That's SO WEIRD.

[mattstratton]

OK, reverting that change didn't affect the build time of partials/head, so it might just be my computer being slow. I'm going to reboot and will run templateMetrics again :)

[mattstratton]

Same results after a reboot on my side and a machine that isn't doing anything else, so I don't think the increase in time is related to that og:updated_time change, but maybe just a function of having one whole year's worth more files?

[mattstratton]

I suspect that this code (which exists on partials/head/open_graph.html and partials/head/twitter_cards.html is partially to blame:

  {{- $e := (index $.Site.Data.events (index (split (.Permalink | relURL) "/") 2)) -}}

On every single, welcome, talk, speaker, speakers, and program page, that query gets executed twice just to build the <head> meta tags.

One thing that could help (I don't quite understand how cumulative these things are) would be to combine all the partials in head/seo into a single partial; this way the single partial would be able to use one data query instead of having to do it multiple times for open graph AND for twitter code.

[mattstratton]

PR #7950 combines all the SEO templates into a single template; on my local machine this cut 30s off of the hugo build. If the PR passes, I'll merge it :)

[mattstratton]

PR #7950 has been merged :)

[mattstratton]

Just ran template metrics again, so these are the templates to continue to target:

     cumulative       average       maximum
       duration      duration      duration  count  template
     ----------      --------      --------  -----  --------
  4m6.447973961s  1.825540547s  6.223745544s    135  program/single.html
  2m28.885470424s   56.545943ms  268.589389ms   2633  speaker/single.html
  1m31.734827266s   12.821079ms  4.069035612s   7155  partials/head.html
  1m27.452857839s   12.222621ms  4.068451169s   7155  partials/head/seo.html

[mattstratton]

For the record, since these happen in parallel, it doesn't do a lot of good to optimize anything other than the program page first (it's the one that takes the longest). Even if we make speaker/single.html faster, for example, the entire build is still going to take a long time.

One thing that is weird is that the build above took 157798 ms, which is 2.6 minutes, but the program pages report as taking 4 minutes. Go figure.

[mattstratton]

Aha. The durations for template metrics are based on CPU time, not elapsed time.

[mattstratton]

I had a thought on how we could improve the performance of the speaker/single.html template, but it's not super awesome.

Right now, part of why it's so slow and intensive is this set of code:

<div class="speaker-bio-talks">
     <h3>{{ .Title }} at {{ $e.city }} {{$e.year}}</h3>
          <ul class="list-group">
            {{- $.Scratch.Set "speaker" .File.BaseFileName -}}
            {{ range where (where $.Site.Pages "Type" "talk") ".File.Dir" "=" 
(print "events/" $e.name "/program/") }}
                <!-- Now we can display stuff! -->
                {{- range .Params.speakers -}}
                  {{- if eq . ($.Scratch.Get "speaker") -}}
                    {{- $.Scratch.Set "display" "true" -}}
                  {{- end -}}
                {{- end -}}
                {{- if eq ($.Scratch.Get "display") "true" -}}
                  <a href = "{{ .Permalink }}" class= "list-group-item 
list-group-item-action">{{ .Title }}</a>
                  {{ $.Scratch.Set "display" "false" }}
                {{- end -}}
            {{- end -}} <!-- end range where -->
          </ul>
          </div>
  </div>

Let's walk through this and understand what it's doing (fyi, this is what shows the "Michael Bluth at Ponyville 2020" widget with the talks at that event from this speaker):

$.Scratch.Set "speaker" .File.BaseFileName

This takes the value of the .File.BaseFileName of the page being constructed (if the page is michael-bluth.md, the value is "michael-bluth") and shoves it into Scratch variable called "speaker".

range where (where $.Site.Pages "Type" "talk") ".File.Dir" "=" (print "events/"
 $e.name "/program/")

This executes a query against all the pages of type "talk" in the content/events/YYYY-city/program/ directory, which it will then iterate over.

range .Params.speakers

This query executes on every "talk" page it finds in the event's program directory. It steps through all the values in the array speakers that it finds in the frontmatter for that talk.

{{- if eq . ($.Scratch.Get "speaker") -}}
  {{- $.Scratch.Set "display" "true" -}}
{{- end -}}

Stepping through each of the values in the array, if the current value of the array item matches what is in Scratch for "speaker", it sets a value of "true" to the Scratch variable "display".

{{- if eq ($.Scratch.Get "display") "true" -}}
  <a href = "{{ .Permalink }}" class= "list-group-item 
list-group-item-action">{{ .Title }}</a>
  {{ $.Scratch.Set "display" "false" }}
{{- end -}}

If "display" is currently "true", it generates the HTML to create the link to the talk. It then sets "display" back to "false"

So, there are a few things that are less than efficient. One thing that comes to mind is that the Scratch variable of "display" may no longer be needed. We can possibly just do this:

{{- if eq . ($.Scratch.Get "speaker") -}}
	<a href = "{{ .Permalink }}" class= "list-group-item 
list-group-item-action">{{ .Title }}</a>
{{- end -}}

I suspect there was a reason in the past to use the scratch variable for this (usually we use them because nesting if statements in Go templates is an issue for variable scope, but I don't see anything in here that would be an issue.

That being said, the biggest problem is that for every speaker, we have to query and load all the talks from that event. It's a small thing but it can definitely add up, as there are a lot of Speaker pages.

The possible solution is to add a bit of frontmatter to the speakername.md file, which would look like this:

talks = "[michael-bluth]"

This would basically embed the talks that this speaker is giving at that event inside the frontmatter of the speaker page. So let's say that Michael Bluth is giving two talks: one by himself and one with George Bluth. The frontmatter would look like this:

talks = "michael-bluth", "george-and-michael-bluth"]

In the template, we would no longer have to do the lookups at all on the pages of type talk; we would simply generate the HTML links while stepping through
.Params.talks.

But there's a problem. We need the title of the talk, and we won't have that from the frontmatter.

So basically, I've just realized this potential solution doesn't work. I'm keeping this in this comment in case it spurs another idea.

[mattstratton]

Spinning off older events to static had a non-trivial impact on the build, so yay.

Here's what it used to be:

     cumulative       average       maximum
       duration      duration      duration  count  template
     ----------      --------      --------  -----  --------
  4m6.447973961s  1.825540547s  6.223745544s    135  program/single.html
  2m28.885470424s   56.545943ms  268.589389ms   2633  speaker/single.html
  1m31.734827266s   12.821079ms  4.069035612s   7155  partials/head.html
  1m27.452857839s   12.222621ms  4.068451169s   7155  partials/head/seo.html

now it looks like this:

    cumulative       average       maximum
       duration      duration      duration  count  template
     ----------      --------      --------  -----  --------
  1m20.521676812s  936.298567ms  2.475422152s     86  program/single.html
  1m2.125752735s   38.254773ms  230.968171ms   1624  speaker/single.html
  54.306623225s    12.24225ms    4.7990159s   4436  partials/head.html
  51.763550073s   11.668969ms  4.797610796s   4436  partials/head/seo.html
  19.808843368s   22.690542ms  4.829697529s    873  event/single.html

I have no idea why the average duration for program/single.html is cut in half, but maybe the older program files were slower for some reason? LOL

[mattstratton]

I will say that thinking about this now and looking at the average duration being less than a second, archiving off to static is the most effective way of trimming the build; making the program page generate faster is less impactful than just having to do it less frequently?

[tgross]

I have no idea why the average duration for program/single.html is cut in half, but maybe the older program files were slower for some reason? LOL

That page iterates over all the talks and all the speakers, I think? So pulling a bunch of old content out of the build should really reduce the length of those loops.

[mattstratton]

Tim, you are a smart cookie. I had repressed the fact that I looped over ALL talks, not just the ones for that event :)