partialCached slows down Hugo (much)

[Jos512]

PS I:\site\website> hugo env
Hugo Static Site Generator v0.18.1 BuildDate: 2016-12-30T10:03:28+01:00
GOOS="windows"
GOARCH="amd64"
GOVERSION="go1.7.4"

In the footer of each page, I reference the following partial:

{{ partialCached "cached/footer-morearticles.html" . .RelPermalink }}

That partial contains:

<!-- List of recent articles -->
<ul>
  {{ if not (eq .Section "") }}

    {{ range (where .Site.Pages "Section" .Section) | shuffle | first 6 }}
      <li><a href="{{ .Permalink }}" title="{{ .Title }}">{{ .Title }}</a></li>
    {{ end }}

  {{ else }}

    {{ range first 6 .Site.Pages }}
      {{ if not (eq .Section "") }}
        <li><a href="{{ .Permalink }}" title="{{ if isset .Params "categories" }}{{ index .Params.categories 0}} - {{ end }}{{ .Title }}">{{ .Title }}</a></li>
      {{ end }}
    {{ end }}

  {{ end }}
</ul>

Now when I try to build Hugo (hugo server --buildDrafts), it takes a tremendous amount of time before Hugo builds. For instance, here I waited more than 5 minutes and Hugo still hadn't build:

PS I:\site\website> hugo server --buildDrafts | timestamp
 8:38:08 Started building sites ...
PS I:\site\website> timestamp
 8:44:21

Now if I don't use partialCached but instead a regular partial:

{{ partial "cached/footer-morearticles.html" . }}

And I don't change anything else in my theme, then the Hugo build time is less than 2 seconds:

PS I:\site\website> hugo server --buildDrafts | timestamp
 8:35:58 Started building sites ...
 8:36:00 Built site for language en:
 8:36:00 36 of 36 drafts rendered
 8:36:00 0 future content
 8:36:00 0 expired content
 8:36:00 402 regular pages created
 8:36:00 5 other pages created
 8:36:00 0 non-page files copied
 8:36:00 0 paginator pages created
 8:36:00 0 n1 created
 8:36:00 0 n2 created
 8:36:00 total in 1690 ms
 8:36:00 Watching for changes in I:\site\website\{data,content,layouts,static,themes}
 8:36:00 Serving pages from memory
 8:36:00 Web Server is available at http://localhost:1313/ (bind address 127.0.0.1)
 8:36:00 Press Ctrl+C to stop

I of course referenced the partialCached documentation, but I'm not seeing anything in the way that I use partialCached to explain this behaviour.

---

To help troubleshoot, the issue also happens when I use:

{{ partialCached "cached/footer-morearticles.html" . }}

So it doesn't seem to be caused by using an unique cache key.

That seems to suggest that one of the functions used in the partial don't work nicely with partialCached. I tried to rule out that myself, but:

• Removing shuffle from the partial had no effect (problem persisted).
• Removing first 6 from partial had no effect.
• Removing the 'piping operation' ( | shuffle | first 6) had no effect.
• Changing .Site.Pages to the new .Site.RegularPages had no effect.
• Replacing (where .Site.RegularPages "Section" .Section) with .Site.RegularPages to rule out where had no effect.

---

To rule out even more, on my pages I used this:

{{ partialCached "foot.html" . }}

Now when I change that to partial (instead of partialCached) and in foot.html use the following code:

{{ partialCached "cached/footer-morearticles.html" .Permalink }}

Then the same problem happens (Hugo remains stuck on 'Started building sites...'). So it doesn't seem to be caused by a cached partial that references a cached partial.

---

If you have other ideas I can test, let me know.

[bep]

I cannot reproduce this on my Mac, which means that it is either

1. A Windows issue ...?
2. Something about your Hugo project that I don't see. Is it on GitHub for me to look at/test?

[Jos512]

(1) That might be, I'm using Windows 7 SP 1 (64bit) with Hugo 64 bit.

(2) It's unfortunately not on Github (it's a paid membership kind of site).

(Thanks for the quick reply, by the way. And that even during the weekend. :) )

---

My previous step to reproduce listed above might be incorrect. After I removed all partialCached entries from my theme, this morning I re-added the 'offending' line:

{{ partialCached "cached/footer-morearticles.html" . .RelPermalink }}

Now the problem did not happen.

Optimistically, I re-introduced my second partialCached at the bottom of my index page:

{{ partialCached "foot.html" . }}

And then the problem re-appeared.

So I took these steps:

1. Added the cached partial that's referenced in foot.html.
2. Then made foot.html a cached partial itself on my index page.

The output for these two steps is:

PS I:\site\website> hugo server --buildDrafts --stepAnalysis | timestamp
 8:41:35 Started building sites ...
 8:41:35 Go initialization:
 8:41:35        737.0422ms (738.0422ms)    94.18 MB     154119 Allocs
 8:41:35 initialize & template prep:
 8:41:35        27.0015ms (765.0437ms)      1.20 MB     17465 Allocs
 8:41:35 load data:
 8:41:35        1.0001ms (766.0438ms)       0.01 MB     138 Allocs
 8:41:35 load i18n:
 8:41:35        0s (766.0438ms)     0.01 MB     155 Allocs
 8:41:35 read pages from source:
 8:41:35        165.0094ms (931.0532ms)    49.40 MB     737382 Allocs
 8:41:35 convert source:
 8:41:35        135.0078ms (1.066061s)     94.87 MB     359306 Allocs
 8:41:35 build Site meta:
 8:41:35        26.0014ms (1.0920624s)      2.46 MB     61224 Allocs
 8:41:35 prepare pages:
 8:41:35        176.0101ms (1.2690726s)   148.09 MB     464812 Allocs
 8:41:35 render and write aliases:
 8:41:35        2.0001ms (1.2710727s)       0.20 MB     3133 Allocs
 8:41:36 render and write pages:
 8:41:36        1.0540603s (2.325133s)    255.17 MB     6793911 Allocs
 8:41:36 render and write Sitemap:
 8:41:36        15.0008ms (2.3401338s)      0.94 MB     24270 Allocs
 8:41:36 render and write robots.txt:
 8:41:36        0s (2.3401338s)     0.00 MB     11 Allocs
 8:41:36 render and write 404:
 8:41:36        6.0004ms (2.3461342s)       0.45 MB     13509 Allocs
 8:41:36 Built site for language en:
 8:41:36 36 of 36 drafts rendered
 8:41:36 0 future content
 8:41:36 0 expired content
 8:41:36 402 regular pages created
 8:41:36 5 other pages created
 8:41:36 0 non-page files copied
 8:41:36 0 paginator pages created
 8:41:36 0 n1 created
 8:41:36 0 n2 created
 8:41:36 total in 1608 ms
 8:41:36 Watching for changes in I:\site\website\{data,content,layouts,static,themes}
 8:41:37 Serving pages from memory
 8:41:37 Web Server is available at http://localhost:1313/ (bind address 127.0.0.1)
 8:41:37 Press Ctrl+C to stop
 8:42:01
 8:42:02 Change detected, rebuilding site
 8:42:02 2017-01-15 08:42 +0100
 8:42:02 initialize rebuild:
 8:42:02        25.1024357s (27.4485699s)           8.31 MB     51476 Allocs
 8:42:02 Template changed I:\site\website\themes\lanyon\layouts\index.html
 8:42:02 template prep:
 8:42:02        26.0015ms (27.4745714s)     1.03 MB     17444 Allocs
 8:42:02 read & convert pages from source:
 8:42:02        1.0001ms (27.4805718s)      0.00 MB     11 Allocs
 8:42:02 prepare pages:
 8:42:02        128.0074ms (27.6105792s)          128.69 MB     470251 Allocs
 8:42:02 render and write aliases:
 8:42:02        1.0001ms (27.6125793s)      0.11 MB     1722 Allocs
PS I:\site\website> timestamp
 8:49:14

Here at 8:42:02 I made foot.html a cached partial in index.html. That made Hugo stuck on the 'render and write pages' step.

Some observations:

• If I kill hugo, close PowerShell, and then try to rebuild the site again (hugo server --buildDrafts --stepAnalysis) the problem still appears. So it doesn't seem to be a memory issue when hugo watches & rebuilds.
• Using the --ignoreCache flag doesn't affect this (problem persists).

---

When I build Hugo to disk (hugo --buildDrafts --stepAnalysis) I get the error message shown below. I don't know if this error message is related or not, but it's the first time I see it:

PS I:\site\website> hugo --buildDrafts --stepAnalysis | timestamp
9:06:32 Started building sites ...
9:06:32 Go initialization:
9:06:32 9.2515292s (9.2535292s) 30.10 MB 174627 Allocs
9:06:32 initialize & template prep:
9:06:32 35.002ms (9.2885312s) 1.20 MB 17484 Allocs
9:06:32 load data:
9:06:32 0s (9.2885312s) 0.01 MB 138 Allocs
9:06:32 load i18n:
9:06:32 1.0001ms (9.2895313s) 0.01 MB 155 Allocs
9:06:32 read pages from source:
9:06:32 214.0122ms (9.5035435s) 49.41 MB 737544 Allocs
9:06:32 convert source:
9:06:32 123.0071ms (9.6265506s) 95.02 MB 359418 Allocs
9:06:32 build Site meta:
9:06:32 27.0015ms (9.6535521s) 2.46 MB 61224 Allocs
9:06:32 prepare pages:
9:06:32 178.0102ms (9.8315623s) 135.36 MB 464265 Allocs
9:06:32 render and write aliases:
9:06:32 18.001ms (9.8495633s) 0.22 MB 3180 Allocs
fatal error: all goroutines are asleep - deadlock!

goroutine 1 [semacquire]:
sync.runtime_Semacquire(0xc042697e8c)
/usr/local/Cellar/go/1.7.4/libexec/src/runtime/sema.go:47 +0x37
sync.(*WaitGroup).Wait(0xc042697e80)
/usr/local/Cellar/go/1.7.4/libexec/src/sync/waitgroup.go:131 +0x9e
github.com/spf13/hugo/hugolib.(*Site).renderPages(0xc0423f3680, 0xb0a8fb, 0x18)
/Users/bep/go/src/github.com/spf13/hugo/hugolib/site_render.go:55 +0x224
github.com/spf13/hugo/hugolib.(*Site).render(0xc0423f3680, 0xc0423f3680, 0xc0423f3680)
/Users/bep/go/src/github.com/spf13/hugo/hugolib/site.go:832 +0xdf
github.com/spf13/hugo/hugolib.(*HugoSites).render(0xc042352680, 0xc0422c0700, 0x0, 0x0)
/Users/bep/go/src/github.com/spf13/hugo/hugolib/hugo_sites_build.go:186 +0x6c
github.com/spf13/hugo/hugolib.(*HugoSites).Build(0xc042352680, 0x100, 0x0, 0x0, 0x0, 0x0, 0x0, 0xa2cb60, 0xc042322410)
/Users/bep/go/src/github.com/spf13/hugo/hugolib/hugo_sites_build.go:58 +0x173
github.com/spf13/hugo/commands.buildSites(0x0, 0x0, 0x0)
/Users/bep/go/src/github.com/spf13/hugo/commands/hugo.go:669 +0xd8
github.com/spf13/hugo/commands.build(0x0, 0x0, 0x0, 0x0, 0x0)
/Users/bep/go/src/github.com/spf13/hugo/commands/hugo.go:447 +0xa0
github.com/spf13/hugo/commands.glob..func8(0xe413a0, 0xc0422c04c0, 0x0, 0x2, 0x0, 0x0)
/Users/bep/go/src/github.com/spf13/hugo/commands/hugo.go:124 +0x84
github.com/spf13/hugo/vendor/github.com/spf13/cobra.(*Command).execute(0xe413a0, 0xc042007f60, 0x2, 0x2, 0xe413a0, 0xc04
2007f60)
/Users/bep/go/src/github.com/spf13/hugo/vendor/github.com/spf13/cobra/command.go:632 +0x245
github.com/spf13/hugo/vendor/github.com/spf13/cobra.(*Command).ExecuteC(0xe413a0, 0xb72788, 0x40e484, 0xe4a1d0)
/Users/bep/go/src/github.com/spf13/hugo/vendor/github.com/spf13/cobra/command.go:722 +0x36e
github.com/spf13/hugo/commands.Execute()
/Users/bep/go/src/github.com/spf13/hugo/commands/hugo.go:160 +0x74
main.main()
/Users/bep/go/src/github.com/spf13/hugo/main.go:26 +0x39

goroutine 852 [chan receive]:
github.com/spf13/hugo/hugolib.errorCollator(0xc044bd1b60, 0xc044bd1c20)
/Users/bep/go/src/github.com/spf13/hugo/hugolib/site.go:1609 +0x94
created by github.com/spf13/hugo/hugolib.(*Site).renderPages
/Users/bep/go/src/github.com/spf13/hugo/hugolib/site_render.go:38 +0xc6

goroutine 853 [semacquire]:
sync.runtime_Semacquire(0xe49b0c)
/usr/local/Cellar/go/1.7.4/libexec/src/runtime/sema.go:47 +0x37
sync.(*RWMutex).RLock(0xe49b00)
/usr/local/Cellar/go/1.7.4/libexec/src/sync/rwmutex.go:43 +0x64
github.com/spf13/hugo/tpl.(*partialCache).Get(0xe49b00, 0xc047eae8a0, 0x20, 0xc0421b6881, 0x1f, 0xaf3ac0, 0xc042a76480,
0xc0453de118, 0x6582d8)
/Users/bep/go/src/github.com/spf13/hugo/tpl/template_funcs.go:1472 +0x51
github.com/spf13/hugo/tpl.partialCached(0xc0421b6881, 0x1f, 0xaf3ac0, 0xc042a76480, 0xc0475bb6c0, 0x1, 0x1, 0x0, 0x0)
/Users/bep/go/src/github.com/spf13/hugo/tpl/template_funcs.go:1503 +0xef
reflect.Value.call(0xa55820, 0xb72b10, 0x13, 0xaf60d0, 0x4, 0xc04319b6d0, 0x3, 0x3, 0xc047eae6e0, 0x1, ...)
/usr/local/Cellar/go/1.7.4/libexec/src/reflect/value.go:434 +0x5cf
reflect.Value.Call(0xa55820, 0xb72b10, 0x13, 0xc04319b6d0, 0x3, 0x3, 0xe0e500, 0xc042178a20, 0xa2cb60)
/usr/local/Cellar/go/1.7.4/libexec/src/reflect/value.go:302 +0xab
text/template.(*state).evalCall(0xc0453deb40, 0xaf3ac0, 0xc042a76480, 0x16, 0xa55820, 0xb72b10, 0x13, 0xe0e440, 0xc04217
89c0, 0xc0421b6872, ...)
/usr/local/Cellar/go/1.7.4/libexec/src/text/template/exec.go:658 +0x537
text/template.(*state).evalFunction(0xc0453deb40, 0xaf3ac0, 0xc042a76480, 0x16, 0xc0421789f0, 0xe0e440, 0xc0421789c0, 0x
c0423011c0, 0x4, 0x4, ...)
/usr/local/Cellar/go/1.7.4/libexec/src/text/template/exec.go:530 +0x19c
text/template.(*state).evalCommand(0xc0453deb40, 0xaf3ac0, 0xc042a76480, 0x16, 0xc0421789c0, 0x0, 0x0, 0x0, 0xc0453de990
, 0x6d0d66, ...)
/usr/local/Cellar/go/1.7.4/libexec/src/text/template/exec.go:427 +0x6fe
text/template.(*state).evalPipeline(0xc0453deb40, 0xaf3ac0, 0xc042a76480, 0x16, 0xc0422d7ea0, 0x0, 0x0, 0x98)
/usr/local/Cellar/go/1.7.4/libexec/src/text/template/exec.go:400 +0xf5
text/template.(*state).walk(0xc0453deb40, 0xaf3ac0, 0xc042a76480, 0x16, 0xe0e2c0, 0xc0422fce70)
/usr/local/Cellar/go/1.7.4/libexec/src/text/template/exec.go:226 +0x42a
text/template.(*state).walk(0xc0453deb40, 0xaf3ac0, 0xc042a76480, 0x16, 0xe0e620, 0xc0422fce10)
/usr/local/Cellar/go/1.7.4/libexec/src/text/template/exec.go:234 +0x144
text/template.(*Template).execute(0xc0421a3c40, 0xe04da0, 0xc0440592d0, 0xaf3ac0, 0xc042a76480, 0x0, 0x0)
/usr/local/Cellar/go/1.7.4/libexec/src/text/template/exec.go:189 +0x20b
text/template.(*Template).Execute(0xc0421a3c40, 0xe04da0, 0xc0440592d0, 0xaf3ac0, 0xc042a76480, 0x18, 0xc0422fcdb0)
/usr/local/Cellar/go/1.7.4/libexec/src/text/template/exec.go:175 +0x5a
html/template.(*Template).Execute(0xc0422fcdb0, 0xe04da0, 0xc0440592d0, 0xaf3ac0, 0xc042a76480, 0xc047ecb540, 0x17)
/usr/local/Cellar/go/1.7.4/libexec/src/html/template/template.go:104 +0x7f
github.com/spf13/hugo/tpl.executeTemplate(0xaf3ac0, 0xc042a76480, 0xe04da0, 0xc0440592d0, 0xc047ecb4e0, 0x2, 0x2)
/Users/bep/go/src/github.com/spf13/hugo/tpl/template.go:133 +0x108
github.com/spf13/hugo/tpl.ExecuteTemplateToHTML(0xaf3ac0, 0xc042a76480, 0xc047ecb4e0, 0x2, 0x2, 0x0, 0x0)
/Users/bep/go/src/github.com/spf13/hugo/tpl/template.go:150 +0xbc
github.com/spf13/hugo/tpl.partial(0xc04216cf68, 0x9, 0xc0453dee60, 0x1, 0x1, 0x0, 0x0)
/Users/bep/go/src/github.com/spf13/hugo/tpl/template.go:120 +0x18c
github.com/spf13/hugo/tpl.(*partialCache).Get(0xe49b00, 0xc04216cf68, 0x9, 0xc04216cf68, 0x9, 0xaf3ac0, 0xc042a76480, 0x
c0453def80, 0x6582d8)
/Users/bep/go/src/github.com/spf13/hugo/tpl/template_funcs.go:1482 +0x1d5
github.com/spf13/hugo/tpl.partialCached(0xc04216cf68, 0x9, 0xaf3ac0, 0xc042a76480, 0xe68410, 0x0, 0x0, 0x0, 0x0)
/Users/bep/go/src/github.com/spf13/hugo/tpl/template_funcs.go:1503 +0xef
reflect.Value.call(0xa55820, 0xb72b10, 0x13, 0xaf60d0, 0x4, 0xc043539380, 0x3, 0x2, 0xc047ecb4a0, 0x1, ...)
/usr/local/Cellar/go/1.7.4/libexec/src/reflect/value.go:434 +0x5cf
reflect.Value.Call(0xa55820, 0xb72b10, 0x13, 0xc043539380, 0x2, 0x2, 0xe0e4a0, 0xc042276140, 0xaf3ac0)
/usr/local/Cellar/go/1.7.4/libexec/src/reflect/value.go:302 +0xab
text/template.(*state).evalCall(0xc0453df9a8, 0xaf3ac0, 0xc042a76480, 0x16, 0xa55820, 0xb72b10, 0x13, 0xe0e440, 0xc0422b
2f90, 0xc04216cf59, ...)
/usr/local/Cellar/go/1.7.4/libexec/src/text/template/exec.go:658 +0x537
text/template.(*state).evalFunction(0xc0453df9a8, 0xaf3ac0, 0xc042a76480, 0x16, 0xc0422b2fc0, 0xe0e440, 0xc0422b2f90, 0x
c042009600, 0x3, 0x4, ...)
/usr/local/Cellar/go/1.7.4/libexec/src/text/template/exec.go:530 +0x19c
text/template.(*state).evalCommand(0xc0453df9a8, 0xaf3ac0, 0xc042a76480, 0x16, 0xc0422b2f90, 0x0, 0x0, 0x0, 0xc0453df7f8
, 0x6d0d66, ...)
/usr/local/Cellar/go/1.7.4/libexec/src/text/template/exec.go:427 +0x6fe
text/template.(*state).evalPipeline(0xc0453df9a8, 0xaf3ac0, 0xc042a76480, 0x16, 0xc0421df540, 0x0, 0x0, 0x98)
/usr/local/Cellar/go/1.7.4/libexec/src/text/template/exec.go:400 +0xf5
text/template.(*state).walk(0xc0453df9a8, 0xaf3ac0, 0xc042a76480, 0x16, 0xe0e2c0, 0xc0422b2ff0)
/usr/local/Cellar/go/1.7.4/libexec/src/text/template/exec.go:226 +0x42a
text/template.(*state).walk(0xc0453df9a8, 0xaf3ac0, 0xc042a76480, 0x16, 0xe0e620, 0xc0422ef650)
/usr/local/Cellar/go/1.7.4/libexec/src/text/template/exec.go:234 +0x144
text/template.(*Template).execute(0xc042300740, 0xe04da0, 0xc043d23880, 0xaf3ac0, 0xc042a76480, 0x0, 0x0)
/usr/local/Cellar/go/1.7.4/libexec/src/text/template/exec.go:189 +0x20b
text/template.(*Template).Execute(0xc042300740, 0xe04da0, 0xc043d23880, 0xaf3ac0, 0xc042a76480, 0xc0451e3ab0, 0x10)
/usr/local/Cellar/go/1.7.4/libexec/src/text/template/exec.go:175 +0x5a
html/template.(*Template).Execute(0xc0422ef5f0, 0xe04da0, 0xc043d23880, 0xaf3ac0, 0xc042a76480, 0x10, 0xc0422ef5f0)
/usr/local/Cellar/go/1.7.4/libexec/src/html/template/template.go:104 +0x7f
github.com/spf13/hugo/hugolib.(*Site).renderThing(0xc0423f3680, 0xaf3ac0, 0xc042a76480, 0xc0451e3ab0, 0x10, 0xe04da0, 0x
c043d23880, 0xa2cb60, 0x5d002a)
/Users/bep/go/src/github.com/spf13/hugo/hugolib/site.go:1851 +0x9d
github.com/spf13/hugo/hugolib.(*Site).renderForLayouts(0xc0423f3680, 0xaf829e, 0x5, 0xaf3ac0, 0xc042a76480, 0xe04da0, 0x
c043d23880, 0xc047ae6900, 0x8, 0x8, ...)
/Users/bep/go/src/github.com/spf13/hugo/hugolib/site.go:1823 +0xd4
github.com/spf13/hugo/hugolib.(*Site).renderAndWritePage(0xc0423f3680, 0xaf829e, 0x5, 0xaf50f5, 0x1, 0xaf3ac0, 0xc042a76
480, 0xc047ae6900, 0x8, 0x8, ...)
/Users/bep/go/src/github.com/spf13/hugo/hugolib/site.go:1730 +0x127
github.com/spf13/hugo/hugolib.pageRenderer(0xc0423f3680, 0xc044bd1bc0, 0xc044bd1b60, 0xc042697e80)
/Users/bep/go/src/github.com/spf13/hugo/hugolib/site_render.go:73 +0x3e5
created by github.com/spf13/hugo/hugolib.(*Site).renderPages
/Users/bep/go/src/github.com/spf13/hugo/hugolib/site_render.go:46 +0x16a

This error happens with the behaviour described above: creating a cached partial that's referenced in foot.html, and making foot.html itself a cached partial too.

---

Let me know if I can help by testing out some ideas.

[Jos512]

I can replicate the same issue on another site of mine. If it helps, I can upload a zip file with that site here. (It's on Bitbucket so not publicly browsable.)

I'm a little doubtful if I should do that already, because I don't want to give the impression that this issue is very urgent for me (it's not) and I don't want to provide even more stuff to go through. That might be offputting and adding more work then needed. So let me know what would help you best.

[bep]

I can replicate the same issue on another site of mine. If it helps, I can upload a zip file with that site here.

Please do, it is the only (practical) way we can fix this -- this is not at the top of my (or others) list, but the zip file will wait there for someone to pick up.

[Jos512]

Okay, I've uploaded the zip file here: [removed].

To replicate the issue, go to the \themes\ghostwriter\layouts folder and open index.html. In the bottom of that file, I've included the explanation and replication information.

[github-actions]

This issue has been automatically locked since there has not been any recent activity after it was closed. Please open a new issue for related bugs.