Compile times are slow

[evanmiller]

My Uzu project is growing in size now (60+ templates, totaling 1 MB of Mustache files) and compile times are now at 5+ minutes. I'd like to put in a request for performance improvements -- it seems like compiling templates in parallel would be a relatively easy speed-up. Profiling shows a lot of time spent in the GC, but I didn't dig in to see if that's an issue with Mustache, or what.

I'm amenable to other solutions, such as putting large blobs of HTML in their own (non-parsed, non-compiled) files. Another possible solution that would alleviate the pain would be allowing piecemeal builds (e.g. uzu build pages/about/).

[scmorrison]

Hi @evanmiller, I have made an initial stab at this. Can you give me some new numbers on your render time?

For now this runs the render steps as Promises. Any performance improvements will depend on the rakudo version you are using.

I like your idea for doing the piecemeal builds. I will see what I can come up with.

[evanmiller]

Thanks. I'm getting a nasty error when I try to install now:

$ zef install .
===> Testing: Uzu:ver('0.2.1')
moar(56752,0x7000019d0000) malloc: *** error for object 0x7fa19f4d1310: pointer being freed was not allocated
*** set a breakpoint in malloc_error_break to debug

Looks like a VM bug, so I'll update Rakudo and try again. Just so I don't forget, the current build time for my project is:

$ time uzu build
Clear old files
Create build directory
Copy public, assets
Compile templates [en]
Compile complete
      438.40 real       366.75 user        59.23 sys

[evanmiller]

Compiling appears to be deadlocked, with 0% CPU used by moar.

$ perl6 --version
This is Rakudo version 2017.07-148-g5fcce6732 built on MoarVM version 2017.07-382-g348b4262
implementing Perl 6.c.

Last output:

$ time uzu build
Use of Nil in string context
  in block  at /Users/emiller/Code/rakudo/install/share/perl6/site/sources/9D54CB20630A6D95A459E8D21558CE9627DA4464 (YAMLish) line 145
Invalid template yaml [/Users/emiller/Websites/evanmiller.next/pages/joy-of-erlang.mustache]
Use of Nil in string context
  in block  at /Users/emiller/Code/rakudo/install/share/perl6/site/sources/9D54CB20630A6D95A459E8D21558CE9627DA4464 (YAMLish) line 145
Invalid template yaml [/Users/emiller/Websites/evanmiller.next/pages/ranking-news-items-with-upvotes.mustache]
Use of Nil in string context
Use of Nil in string context
  in block  at /Users/emiller/Code/rakudo/install/share/perl6/site/sources/9D54CB20630A6D95A459E8D21558CE9627DA4464 (YAMLish) line 145
  in block  at /Users/emiller/Code/rakudo/install/share/perl6/site/sources/9D54CB20630A6D95A459E8D21558CE9627DA4464 (YAMLish) line 145
Invalid template yaml [/Users/emiller/Websites/evanmiller.next/pages/write-a-template-compiler-for-erlang.mustache]
Invalid template yaml [/Users/emiller/Websites/evanmiller.next/pages/why-i-program-in-erlang.mustache]
Invalid template yaml [/Users/emiller/Websites/evanmiller.next/pages/why-im-learning-perl-6.mustache]
Use of Nil in string context
Use of Nil in string context
  in block  at /Users/emiller/Code/rakudo/install/share/perl6/site/sources/9D54CB20630A6D95A459E8D21558CE9627DA4464 (YAMLish) line 145
  in block  at /Users/emiller/Code/rakudo/install/share/perl6/site/sources/9D54CB20630A6D95A459E8D21558CE9627DA4464 (YAMLish) line 145
Invalid template yaml [/Users/emiller/Websites/evanmiller.next/pages/ab-testing/survival-times.mustache]
Invalid template yaml [/Users/emiller/Websites/evanmiller.next/pages/ab-testing/chi-squared.mustache]
Invalid template yaml [/Users/emiller/Websites/evanmiller.next/pages/ab-testing/survival-curves.mustache]
Invalid template yaml [/Users/emiller/Websites/evanmiller.next/pages/sequential-ab-testing.mustache]
Use of Nil in string context
  in block  at /Users/emiller/Code/rakudo/install/share/perl6/site/sources/9D54CB20630A6D95A459E8D21558CE9627DA4464 (YAMLish) line 145
Invalid template yaml [/Users/emiller/Websites/evanmiller.next/partials/list_writings.mustache]
Clear old files
Create build directory
Copy public, assets
Compile templates [en]

[evanmiller]

Looks like a thread-exhaustion issue. Putting use v6.d.PREVIEW at the top of Render.pm resolves the deadlock. For context see https://github.com/rakudo/rakudo/pull/1004

The build does not succeed -- I see a dozens of warnings like:

Use of uninitialized value $key of type Any in string context.
Methods .^name, .perl, .gist, or .say can be used to stringify it to something meaningful.
  in block  at /Users/emiller/Code/rakudo/install/share/perl6/site/sources/519927884D1F03D999B793B24E79F13044D6F2F6 (Template::Mustache) line 200

Then finally:

An operation first awaited:
  in sub build at /Users/emiller/Code/rakudo/install/share/perl6/site/sources/B64B70030D8DC8D24494E45C38BA972A87CF0732 (Uzu::Render) line 401
  in sub MAIN at /Users/emiller/Code/rakudo/install/share/perl6/site/sources/A6A04D2AC064A3AC3AC0CFA1813B60BA00E99C28 (Uzu::CLI) line 38
  in block <unit> at /Users/emiller/Code/rakudo/install/share/perl6/site/resources/2FA4F1086B130C49B85739217FDF9182FFBCD515 line 5
  in sub MAIN at /Users/emiller/Code/rakudo/install/share/perl6/site/bin/uzu line 2
  in block <unit> at /Users/emiller/Code/rakudo/install/share/perl6/site/bin/uzu line 2

Died with the exception:
    Tried to get the result of a broken Promise
      in sub render at /Users/emiller/Code/rakudo/install/share/perl6/site/sources/B64B70030D8DC8D24494E45C38BA972A87CF0732 (Uzu::Render) line 236
      in any  at /Users/emiller/Code/rakudo/install/share/perl6/site/sources/B64B70030D8DC8D24494E45C38BA972A87CF0732 (Uzu::Render) line 388
      in block  at /Users/emiller/Code/rakudo/install/share/perl6/site/sources/B64B70030D8DC8D24494E45C38BA972A87CF0732 (Uzu::Render) line 385

    Original exception:
        No such method 'cache' for invocant of type 'NQPMu'
          in any  at /Users/emiller/Code/rakudo/install/share/perl6/runtime/CORE.d.setting.moarvm line 1
          in any  at /Users/emiller/Code/rakudo/install/share/perl6/runtime/CORE.d.setting.moarvm line 1
          in sub build at /Users/emiller/Code/rakudo/install/share/perl6/site/sources/B64B70030D8DC8D24494E45C38BA972A87CF0732 (Uzu::Render) line 401
          in sub MAIN at /Users/emiller/Code/rakudo/install/share/perl6/site/sources/A6A04D2AC064A3AC3AC0CFA1813B60BA00E99C28 (Uzu::CLI) line 38
          in block <unit> at /Users/emiller/Code/rakudo/install/share/perl6/site/resources/2FA4F1086B130C49B85739217FDF9182FFBCD515 line 5
          in sub MAIN at /Users/emiller/Code/rakudo/install/share/perl6/site/bin/uzu line 2
          in block <unit> at /Users/emiller/Code/rakudo/install/share/perl6/site/bin/uzu line 2

[evanmiller]

After some IRC discussion I've filed a Rakudo bug here: https://rt.perl.org/Ticket/Display.html?id=131888

[scmorrison]

Ok, I have added use v6.d.PREVIEW for now. I am going to follow this closely and add more parallelism as it matures.

[evanmiller]

From my general experience maybe it's best to confine the parallelism to the innermost loop -- e.g. compile individual templates in parallel, but do the languages in sequence. If you saturate all the cores in the innermost loop, then there's not really any added benefit to parallelizing the outer loops.

[evanmiller]

For parallelism without the promise/await stuff, you might check out the .hyper method:

https://docs.perl6.org/routine/hyper

[scmorrison]

I have been messing around with hyper and I am still getting the segfaults. It does seem to be relatively stable on the later rakudo commits though.

[evanmiller]

I filed a second issue against Rakudo regarding segfaults with your previous commits. The Rakudo folks are able to reproduce and seem to be making progress on it. 🤞 https://rt.perl.org/Public/Bug/Display.html?id=131889

[evanmiller]

A second project with 800KB of template files has this compile time:

time uzu --clear build
Create build directory
Copy public, assets
Compile templates [en]
Compile complete
      505.46 real       496.28 user         6.41 sys

Uzu is becoming almost unusably slow for me, 8+ minutes here. I would very much appreciate any efforts to profile and improve performance.

[scmorrison]

I feel your pain. I have added a --page-filteroption to facilitate restricting renders to pages sub-directories.

uzu --page-filter=compute build

This is the current behavior:

• Only templates nested under the filter path will be rendered
• uzu --clear --page-filter=compute build still removes everything from build, but only rebuilds starting from the filter path
• works with both build, and watch
• Parent templates outside the filter path that have *_pages that nested inside the filter path are not re-rendered

It should reduce unnecessary rendering while you are testing, but let me know if you want to refine the behavior in any way.

Also, on a performance related note, the biggest hit right now is that everything happens sequentially. Once we can take advantage of the p6 concurrency features we should be able to get better performance. I did notice that pushing the write tasks to a Channel actually slowed down the renders so I have removed it.

I have created a test script to demonstrate the No such method 'cache' for invocant of type 'NQPMu'errors when trying to use Template::Mustache inside of hyper. I have tested different variations of this script, but the only runs that ever work 100% of the time are standard for loops.

https://gist.github.com/scmorrison/d7506b69e5778381c8374163435ae651

That is a simplified version of where uzu starts tripping over itself. Though hyper seems to work fine for quick tasks.

[evanmiller]

Thanks, I'll give the page filter a shot when I'm working on my websites next.

Your test script has a race condition -- IIRC pushing to an array isn't thread-safe. Try

my @pages = [1..1000].hyper.map: { Template::Mustache.render: ... }

[scmorrison]

Yeah, I have already tried that as well. Same results. Sometimes it throws this too:

Ignoring unrecognized :from() entry Any
  in block  at /home/sam/.perl6/sources/519927884D1F03D999B793B24E79F13044D6F2F6 (Template::Mustache) line 210

[evanmiller]

Do you have a Perlbug RT account? If so it would be great if you contributed your findings here:

https://rt.perl.org/Public/Bug/Display.html?id=131888

[scmorrison]

Thanks, I have added a comment with a link to that gist.

[evanmiller]

It might also be worth raising an issue with Template::Mustache. They might have insight into any non-thread-safe behavior in the library.