New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

partialCached slows down Hugo (much) #2935

Closed
Jos512 opened this Issue Jan 14, 2017 · 5 comments

Comments

Projects
None yet
3 participants
@Jos512

Jos512 commented Jan 14, 2017

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 bep added the Bug label Jan 14, 2017

@bep bep added this to the v0.19 milestone Jan 14, 2017

bep added a commit that referenced this issue Jan 14, 2017

tpl: Fix broken benchmarks
But that did not explain issue #2935:

```
BenchmarkPartial-4                       200000          6452 ns/op        1040 B/op          30 allocs/op
BenchmarkPartialCached-4                 500000          4104 ns/op         544 B/op          14 allocs/op
BenchmarkPartialCachedVariants-4         500000          3398 ns/op         624 B/op          17 allocs/op
```
@bep

This comment has been minimized.

Show comment
Hide comment
@bep

bep Jan 14, 2017

Member

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?
Member

bep commented Jan 14, 2017

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?

@bep bep added the CantReproduce label Jan 14, 2017

@Jos512

This comment has been minimized.

Show comment
Hide comment
@Jos512

Jos512 Jan 15, 2017

(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 commented Jan 15, 2017

(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

This comment has been minimized.

Show comment
Hide comment
@Jos512

Jos512 Jan 17, 2017

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.

Jos512 commented Jan 17, 2017

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

This comment has been minimized.

Show comment
Hide comment
@bep

bep Jan 17, 2017

Member

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.

Member

bep commented Jan 17, 2017

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

This comment has been minimized.

Show comment
Hide comment
@Jos512

Jos512 Jan 17, 2017

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.

Jos512 commented Jan 17, 2017

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.

moorereason added a commit to moorereason/hugo that referenced this issue Jan 17, 2017

tpl: Fix deadlock in cached partials
Cached partials that contained cached partials would create a deadlock.

Fixes #2935

@bep bep closed this in #2945 Jan 18, 2017

bep added a commit that referenced this issue Jan 18, 2017

tpl: Fix deadlock in cached partials
Cached partials that contained cached partials would create a deadlock.

Fixes #2935
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment