Question regarding slow rendering

[dadajuice]

Hello,

I recently updated to the newest version available from Composer (from 2.x) and I've notice an incredible drop in rendering time. It can take up to 4-5 seconds to render. It renders around 1 second when I use the cached files, but when I'm in dev mode I like to always renders my files.

Here's how I'm creating the Pug instance which is the same as the previous version:

$options = [
    'basedir' => ROOT_DIR . '/public',
    'expressionLanguage' => 'js',
    'upToDateCheck' => true,
    'cache' => null
];
$this->pug = new Pug($options);

After that I'm using the renderFile method. So I was wondering what I can do to enhance the performances. I've seen that you have a pugjsoption which uses the pug-cli, but do I really need to install node.js to have better performances?

Thanks a lot!

[kylekatarnls]

Hi,

The very first thing I can tell is: You can use the cache in development since now we handle changes that can occurs in includes and layouts you extend. And if you really have a doubt (files with altered last modified times, a change in some Pug interceptor you plug, etc.), then you can empty the cache directory.

It's what happen when you use pug with express or webpack, you would have an implicit cache even in development mode.

You can also display profiling information to see what's wrong and take too much time: https://phug-lang.com/#profiling

If you identify a specific part very slow, we can investigate deeper it.

[kylekatarnls]

Note: the debug option also make the render slower. It's used to display error lines from original pug templates. If you don't use it, you can set 'debug' => false, to save rendering time.

[dadajuice]

Thanks a lot for your prompt response as always :) Its a great thing to know that the cache handles changes in layouts and includes. Will surely use it afterward. But I'd really like to pin what is causing this degraded performance. I tries the debug option as you noted, but I did not see a difference overall.

I tried the profiling on my heavy page and it took 6 seconds and there were great deal of stuff displayed :P I decided to try the profiling on a much simpler file which contains :

extends layout/layout
block content
  h1 Welcome

And here's the extending layout (basic test stuff)

doctype html
html
  head
    title Example
    meta(charset="utf-8")
  body
    #container
      block content

This renders around 2 seconds (which was rendering almost instantly in my previous version as you would expect). Here's the output I got from the profiling :

Current event: Phug\Renderer\Event\HtmlEvent {
  RenderEvent => renderer.render event
  Buffer => ''
  Error => NULL
  Result => 'Welcome'
  Name => 'renderer.html'
  Params => array (2) [
    '__link' => Phug\Renderer\Event\RenderEvent {
      Method => 'render'
      Input => NULL
      Parameters => array []
      Path => 'app/Views/example.pug'
      Name => 'renderer.render'
      Params => array (2) [
        '__link' => Phug\Renderer\Event\RenderEvent {...}
        '__time' => 0.15490198135375977
      ]
    }
    '__time' => 1.3639957904815674
  ]
}

Previous event: Phug\Renderer\Event\RenderEvent {
  Method => 'render'
  Input => NULL
  Parameters => array []
  Path => 'app/Views/example.pug'
  Name => 'renderer.render'
  Params => array (2) [
    '__link' => Phug\Renderer\Event\RenderEvent {
      Method => 'render'
      Input => NULL
      Parameters => array []
      Path => 'app/Views/example.pug'
      Name => 'renderer.render'
      Params => array (2) [
        '__link' => Phug\Renderer\Event\RenderEvent {...}
        '__time' => 0.1589188575744629
      ]
    }
    '__time' => 0.1589188575744629
  ]
}

For reference here's the option I used for profiling as from your documentation :

$options = [
    ...
    'enable_profiler' => true,
    'profiler' => [
            'timeprecision' => 3,
            'lineheight'    => 30,
            'display'        => true,
            'log'            => false,
    ]
];

I tried passing arguments to be rendered to see if it degraded, but I did not notice any changes. So just this really simple Pug takes around 2 seconds to render (without caching of course) ... So to me it seems coherent that if I have a big Pug it would take around 6 seconds.

Thank you very much again for your time.

[dadajuice]

As a reference here's the profiling output for my heavier page which I removed the unnecessary outputs from my page and my parameters.

Current event: Phug\Renderer\Event\HtmlEvent {
  RenderEvent => renderer.render event
  Buffer => ''
  Error => NULL
  Result => '...'
  Name => 'renderer.html'
  Params => array (2) [
    '__link' => Phug\Renderer\Event\RenderEvent {
      Method => 'render'
      Input => NULL
      Parameters => array (4) [...] (some normal parameters)
      Path => 'app/Views/user-profile.pug'
      Name => 'renderer.render'
      Params => array (2) [
        '__link' => Phug\Renderer\Event\RenderEvent {...}
        '__time' => 0.16382193565368652
      ]
    }
    '__time' => 5.111066818237305
  ]
}

The previous event segment was only of 0.15 like my previous test case so I did not included it.

[kylekatarnls]

Do you have only text output? The timeline does not appear at screen? However, it's normal the profiling is slower to display, it intercept every events to benchmark them.

Something else, if you are on PHP 5, we get very better performances on PHP 7.

Just to have some data to work on. How much time take to render your biggest template (without profiling)?

[dadajuice]

I'd say it takes about the same time. I don't really get a big notable overhead with the profiling. And yes I am currently running on PHP 7.1.

Yes I had the timeline on screen I'll link a screenshot for my basic test. The timeline does not render correctly on my heavy page because I have many fixed components and stuff that overlaps and break it.

[kylekatarnls]

It seems like cached mode, when you render freshly a template, the profiling should show the lexing, parsing, compilation and formatting of each node. And also the rendering should show the render time for each node. That's the usefull info, it allow to locate nodes that take most time.

Then rendering is in fact not a Pug job, it's your code job. I mean if you do 50 big SQL queries in your template, it will appear as rendering process.

You said you upgraded, did you try the same template on both 2.x and 3.x?

[dadajuice]

Yes it was the same template with the same data and processing behind :\ That's what I find weird. And its also weird that I don't have the data your are referring because I have specifically removed the cache to try to locate the problem. I was also wondering how these little info could help haha

I'll try to completely remove my vendor folder and do a fresh composer install maybe something went wrong on my end on the update process. I'll let you know the outcome.

Thank you very much again for your time.

[kylekatarnls]

I don't deny it could be slower because Pug 3 with a lot more features as you can see in the documentation. And we have some plans to improve the situation (#168) on both cached mode (prod) and full process in dev.

I will try to see what could trigger the profiling with only render first and final events.

[dadajuice]

I've tried a fresh install with the same results sadly. I'm sure its something I can do on my end, but I really don't know what.

I can assure you that its the exact same template with the same business logic interacting with the same data I'm using for the past months and it was always rendering within a second without caching. I updated this morning and notice this change.

But I'm 100% sure there's something I'm doing wrong concerning the usage of the new version, but can't find it. Because it would be impossible for you or others to not have notice such a drastic change in performance. I've seen the improvement issue and its couple milliseconds, which of course are extremely important, but my problem is triggering couple seconds.

I'll continue to check my code behind to see if there's something wrong, but for now I may have to rollback to 2.x.

[dadajuice]

If it can be of any help I may have narrowed the problem ... I did downgrading to version 2.7.3, but I had the same problem. I downgraded afterward to version 2.7.2 and it worked like before (it was the exact version I had before). So it seemed I skipped couple versions and jump right in version 3.0 ... I don't know if it can help pin the problem knowing I had it from 2.7.2 -> 2.7.3.

Thanks again!

[kylekatarnls]

Goth, it's an other problem. The tag 2.7.3 is on the wrong branch. First I will tag a 2.7.4 on the right branch.

[kylekatarnls]

Hi again, the Pug options mapping breaks the profiling. Could you try (just to display profiling) to replace your initialization of Pug by this:

$options = [
    'debug' => true,
    'enable_profiler' => true,
    'basedir' => ROOT_DIR . '/public',
    'expressionLanguage' => 'js',
    'upToDateCheck' => true,
    'cache' => null
];
$this->pug = new \Phug\Renderer($options);

Here is what main step looks like with a big template of mine: I get a decent total time and we can identify lexing and then formatting are the longest processes but as it does not exceed 52ms. In my case it's not a problem at all.

Hope we'll be able to get some clues in your profiling.

[dadajuice]

Once again, thank you for your prompt response. I've used the code you provided and I got more details like you.

This one if from my basic test

I tried on my heavier page and got pretty much the same numbers.

[kylekatarnls]

Same numbers? You mean your heavier page takes 770ms to globally render? Or proportional results? You talked about 6 seconds earlier. 770ms (in non-cached mode) is not a slowness concern for me. It's the 6 seconds-timeline I would inspect. If you do not get consistent results when profiling and when you render normally (I mean if you have 1 second on profiling but experienced 6 seconds on render), can you check specific parts of Pug running:

$time = microtime(true);
$options = [
    'basedir' => ROOT_DIR . '/public',
    'expressionLanguage' => 'js',
    'upToDateCheck' => true,
    'cache' => null
];
$this->pug = new Pug($options);
$initDuration = microtime(true) - $time;
// ...
$time = microtime(true);
$this->pug->renderFile(...);
$renderTime = microtime(true) - $time;
echo $initDuration . '<br>' . $renderTime;
exit;

To get the overall pug process durations.

[dadajuice]

Yes I do think under 1s is an amazing performance :D I did the time check you recommended and as expected the problem is in the rendering area.

init time : 0.9803478717804 render time: 4.5117208957672

which results in my around 6 seconds timespan I was talking about for my heavier page.

[dadajuice]

And I forgot to answer, but with my heavier page I had around the same numbers with the settings you provided :

$options = [
    'debug' => true,
    'enable_profiler' => true,
    'basedir' => ROOT_DIR . '/public',
    'expressionLanguage' => 'js',
    'upToDateCheck' => true,
    'cache' => null
];
$this->pug = new \Phug\Renderer($options);

Both cases (simple page and heavier) was around 600-700ms.

[kylekatarnls]

What I don't understand is the profiling do the render and the profiling. Having a faster profiling than the real render has no sense. The last thing that can come is the render capture (capture output and returns it). Could you try the same benchmark with ->displayFile instead of ->renderFile?

[dadajuice]

Yep got the same results with displayFile and renderFile :/

[kylekatarnls]

Hi, would you mind to send your biggest template? If it's something too confidential, you could obfuscate/anonymise it and send it to phug@selfbuild.fr. I suspect it could be a particular pattern that Phug handle slower.

[dadajuice]

Once again, thank you very much for your time.

Yes I can do that, but you won't be able to execute it I think because there's a great deal of stuff happening which depends on the data as you would expect. I will send you an email with a template which takes around 6 seconds and all its dependencies (included files and mixins). Its not the biggest, but all my pages looks about the same anyway, if you find a problematic pattern I may have it elsewhere.

I have rolled back to 2.x to continue my project and its really day and night :P With 2.x all my pages are extremely fast and with 3.x I'm looking around 5-6s per page with the same templates.

[dadajuice]

I also got another benchmark yesterday ... I restarted my server (so all PHP cache was flushed) and got this for the basic page which I posted the code earlier.

I took the screenshot, but forgot to post it. After this initial loading which took a great deal of time, I think PHP cached something and after that it got around 700ms like the last times.

[kylekatarnls]

I can compile your file without rendering the data in it. This lexing time (2221ms) is yet a lot comparing to the apps where I use pug. I will wait for your template, includes files and mixins (should be enough) and I'm working on the Phug profiling tool to fully work in the Pug wrapper.

[dadajuice]

Thank! I've sent the template file with my includes :)

[kylekatarnls]

Sorry, it seems my selfbuild.fr e-mails are down. I opened a ticket on my hosting provider, please re-send it to kylekatarnls@users.noreply.github.com.

I have also a good new. I had an idea for lexing optimization. Right now we have an iterative check. Something like (if it's newline, else if it's a tab, else if it's a parenthesis, etc.) By checking the first character of the lexing string we could have some short-cuts (. to class name, # to id, ( to attribute list, etc.)

[dadajuice]

No problem I forwarded the email to your specified address. Thanks again!

[dadajuice]

I just received a postmaster notice indicating I cannot reach you with your given address :\

[kylekatarnls]

Hi, sorry for that, please use this form: http://pug.selfbuild.fr/

[dadajuice]

Alright I used the form :)

[kylekatarnls]

Thanks. Downloaded.

[kylekatarnls]

Hi,

The character-cache provides very small optimization.

The whole render-time (including init) was very good on my machine (701ms average). But I had to create an empty delete.pug modal to replace this missing file and add to create random functions to replace yours.

I could not test it with Pug-php 2 as there are multiple syntaxes that Pug-php 2 does not support. Could you also send me the templates you compared on 2.7 and 3.1 maybe?

I compared all your files again test-cases sample. It gave close (and fast) times for lexing and parsing.

So it reduces a lot the possibilities.

• You can try to remove delete.pug include (just to be sure it's not something in it).
• Could you check if you have xdebug enabled (use phpinfo() to check it) and try to disable it to compare? (Comment the extension in php.ini and restart server/php listen script)
• Could you check the function/expression you use the most (for example, I saw a href() function)? For example, to benchmark this isolated function:

• i = 0 while i < 100
  • i++ =href('...')

    
    And run it with Pug-php 2.7 and Pug-php 3.1?

Question: do you use a framework, if so, which one?

[dadajuice]

Hi,

Thanks for your reply! Sorry about the delete modal, but this file really doesn't contain much, I did remove it to test and it did not really impact the overall as for disabling xdebug (I used the xdebug_disable() function in my bootstrap file). The functions your are referring are also really simple mostly for string formatting purposes.

I did some testing with caching enabled :

Pug 3.1 Initial rendering: ~6.8 seconds From cache: ~1.2 seconds

Pug 2.7 Initial rendering: ~1.3 seconds From cache: ~0.17 seconds

All my tests are done on the same machine. I'm only changing the Pug version :P Like I previously stated, I also got a really simple base test case which renders around 2 seconds without caching which before was more around 0.6 seconds or so.

And yes I am using a framework which I developed myself for personal projects and for pedagogic purposes (I am a computer science teacher). I decided to make Pug mandatory in my framework, so all the views must be done with Pug :P If you are interested to see how Pug is handled in my framework we can communicate in emails, but its fairly easy setup. I've got a Singleton ViewBuilder which create the Pug instance and later uses it to render a specified file.

Thanks again for your time!

[kylekatarnls]

Hi, 4.7 seconds. At least I'm able to get time that match yours. (I had to create some mock class, functions, constants and data). So it's OK for Pug-php 3 to work with your template.

Now, I need to be sure Pug-php 2 is really better. As the gap seems huge and as I get a syntax error with Pug-php 2, I suspect you can have the same error hidden and it gave your faster times (1.3 and 0.17) than it could be for a complete render with no errors.

I also reached you by mail for details about your framework. I hope we'll be able to make it compatible with Pug-php 3 with no such performance loss and promote it on our frameworks section if you're interested.

[kylekatarnls]

Validated. I now have your complete benchmark with the same template successfully rendered on both 2.7.4 and 3.1.4 (0.55s vs 6.30s). I had to trick some changes to get the same template compatible with both. But here it is a version on which I can work since it's more than 10 times slower. I created bigger samples of templates both compatible 2 and 3 and it seems to be a general problem (not related to a pattern or an implementation).

Cached mode (pure rendering part) and dev mode (compiling part) are different problems and will be treated separately. I consider rendering part has higher priority.

We will not be able to get equivalent performance since Pug-php 2 has much more bugs and much less features. But I'm pretty sure we can find optimizations and reduce this gap.

[dadajuice]

Great! I'm happy that you now have a template to compare results for both version :D

[kylekatarnls]

Small note about the pure rendering runtime part. If you would not use the ->renderFile() method but the ->compileFile() method instead, dump the result in a file, then include manually this cached file (it's what the Laravel adapter currently do, but it is the only one among our framework adapters). Pug-php 3 compiled file will render +/-1% the same than Pug-php 2.

For me, that means this part should not be touched at all (the PHP dumped should remain identical). And we should focus on a way to provide a minimalist function to include a cached file with just locals, shared variables (that would mean short-cut runtime custom events, and runtime options such as the "self" option for example or adapter stuff) but this small sacrifice would provide the fastest rendering for production environments (faster than Pug-php 2 in fact).

Then, for dev-part, it can only be step by step small optimizations.

[kylekatarnls]

New plan for dev-part, first I have to create persostent sourcemap (https://github.com/phug-php/phug/issues/17), this would allow to properly trace exceptions/errors even when rendering a cached file, so the cache could be enabled in development with no impact.

Then we could provide a watcher daemon to compile templates into the cache as soon as they are saved.

I would be similar than what happens right now in Laravel. It's the framework I use the most with Pug-php and one reason for not being bothered by performance is that laravel-mix will re-load the brower (auto-refresh) when any file changed, so when I save a pug template, my browser page is reloaded and the pug compilation immediately start. A quick-check on the code screen and the preview screen already updated. But with a manual refresh, I guess the waiting-feeling matter.

So a standalone watcher or simply provide some live-reload tool ready-to-use could save a lot of time.

What do you think of this idea?

[dadajuice]

Yeah I think that would be a great idea that surely will save a great deal of time :)

[kylekatarnls]

Hi, project started. Until I finish that, you can yet test the production optimizer:

https://phug-lang.com/#usage

You feedback is welcome.

[kylekatarnls]

And here is the watcher util:

https://www.phug-lang.com/#watch

[dadajuice]

Thank you very much for your time on this issue :) I will test the watcher as soon as I can. Thanks again!

[kylekatarnls]

Browser auto-reload released too: https://en.phug-lang.com/#automatically-reload-the-browser-on-change

[pausan]

Hi @kylekatarnls, Let me start saying I believe phug is an awesome project and I know there are countless hours behind it, so from the start you have all my respect.

The thing is, I know you have closed the issue but I don't think it should be closed since the main performance issue is still there. Let me explain. It has been closed because there are two workarounds for it with the watcher / autoreloader, and also the cache, but the reality is that the parser/lexer is still really slow. It should not be that slow. I totally agree the cache is awesome and a must have. The reason I'm using Phug on the first place is to save time programming. While I program websites I do constant changes on the .pug files. To me, production-wise, the cache should be enabled and its performance is great, but in a development phase it is just unacceptable to wait X seconds for something that should be instant (or at least than say 100ms for small files).

I've spent an hour this morning debugging & profiling the code, and while I'm not completely familiar with the scanner/lexer/reader code, I see some stuff going on in the code that makes me suspicious (many loops). I've built myself some parsers & lexers in the past and I'm pretty sure the phug lexer/parser can be made 100x faster (compilation/transformation phase will come later, and I have not checked that one).

I'm not really sure about what kind of token objects are being created, and I'm also wondering if a tokenizer like the native PHP one could be used as a kind of 'hack' to tokenize stuff real quick, I guess not because I think that one skips spaces, ... and for pug parsing, indentation is fundamental. There is also the option to use Parle parser/lexer if only for inspiration to address current performance issues (http://php.net/manual/en/book.parle.php). Using a library like that, or getting inspiration from it might also simplify the code as well.

In any case, would you consider reopening this ticket? I'm superbusy lately, but I'm happy to help if I can.

Let me know your thoughts on this.

[kylekatarnls]

Hi @pausan,

Of course, if I receive a pull-request that makes the lexer 100 times faster without breaking unit tests, I will merge it.

Parle is not built by default with PHP, such a dependency would probably discourage a lot of users, and it would be a breaking change (major release) but if the gain is what you announce it would worth it.

I will not start such a work on my own. If you want the speed, you can use pug-php 2.7, we still maintain it or you may consider using tale-jade as an alternative (but it's no longer maintained) or you can even use pugjs (an easy way is the 'pugjs' => true option) that less extensible and will prevent from using many features but is really faster. If you want the features it come with its cost.

I work on projects using webpack, and the build is far more than few seconds for most of them, I do not consider it as unacceptable. This is still not a must-have from my point of view, while maintaining existing options until next major release is, as pug-php is in use in production applications and is workable as is for many users.

I can understand it seems easy and cost-less from a higher sight to fasten all operations, but your expectation (+9000%) is in reality very high and I'm afraid you would follow a chimera by trying to solve it with a deep refactorization.

I could be more optimistic about some feature like incremental compilation (detect template changes and recompile only the chunks that have changed) or about step-by-step bottlenecks hunting (such as finding a RegExp that is slow with typical templates, replace it with an equivalent method that does not use RegExp, it will fasten by 2%/3%, then seek for the next bottleneck). That seems to me a really more realistic way to improve performance.

[pausan]

I've just checked token_get_all in php and I believe something can be hacked with that (it might be tricky for some expressions, but who knows, maybe it is feasible). It might be fun to experiment a little bit with that. The only thing I need is a little bit of help running the existing tests. I've tried to run tests this morning on that project with no luck. I just cloned phug/lexer repo, not sure if I have to clone more stuff, nor how to launch all tests in that project (I tried with phpunit + script but no luck). If you help me to run existing tests I might play with the code and try something...

Actually... I've just realized I'm in pug-php project, whereas I was referring to phug-php and phug-php/lexer :joy: my fault. Well, you are the owner anyway.

[kylekatarnls]

Basically it would be: clone the GitHub repository, install dependencies with composer install, then run tests using vendor/bin/phug-dev check or for tests only (with no other check and no coverage):

vendor/bin/phpunit -c vendor/phug/dev-tool/config/ --no-coverage