Very slow boot time - please help me find the cause!

[sodesign]

Hello,

One of our sites is suffering from very slow boot times, and I'm not sure how to diagnose the problem.

Here's a grab of the debug panel in Tracy debugger after loading the homepage.

A have a couple of questions -

• Are all of the times listed separate items, or are some of them a breakdown? I ask because the number shown in the tracy debug bar is the total of all of the items but the wording suggests boot.load.modules, boot.load.fields etc are a breakdown of the boot.load.
• How do I find out what these times consist of?

Currently, when using the site, and when running page speed tools, the server load time is consistently upwards of 1s often above 1.5s. This is before the browser even starts downloading resources - a quick grab from my firefox dev tools was even worse:

I would appreciate any advice on finding the cause here.

A few details:

• Server is a digital ocean droplet (2GB memory + 2CPUs) running nginx and php7.0 - neither memory or cpu seem particularly taxed
• Site has 8 locales
• Using template cache and wirecache for heavy pieces of markup
• We're on the latest dev branch - the speed issue has been present for the last couple of versions.
• The speed is similar on when running locally (similar but stripped back nginx config)

 

Thanks,
Tom

[dragan]

The number of hooks and PDO-queries seems rather high.

Did you modify anything (add functionality, change template code...) since you've noticed a slowing down of your site?

Did you turn off debug-mode on your live-site? It really should be.

It could be a number of reasons. Perhaps some modules are autoloaded when not even necessary. Or the way you've built it is not optimized enough. As you probably know - with PW - you can do anything in so many different ways, but some ways of doing stuff is better when you're dealing with lots of content + users. Since a few versions, we have e.g. methods like findIds() or findMany() that can speed things up.

Also, it's a good idea to check if there are new module updates available. Maybe some of them are quite old, and would benefit from an update, performance-wise.

If you need a quick fix, I'd suggest getting the ProCache module. (Perhaps there's a "x days money-back guarantee" that Ryan offers - I'm not sure.

 

 

 

Edited March 16, 2018 by dragan
slight rewording / fixing typo

[sodesign]

Thanks for your reply -

I've been making changes quite frequently - it's a fairly big site to which we're adding a shop. There's no one change which stands out as a huge change.

Debug mode is off on the live site, other than when temporarily testing, and all of the modules are pretty much up to date.

The load times aren't much better when in the admin which is why I haven't spent too much time trying to optimize templates - does template logic affect load time in the admin?

I don't think Procache supports nginx. I was using fastcgi_cache but it gets a little messy with the way we're handling locale redirects - we need to refine our config.

I'd rather find out the reason for the long load times before resorting to a flat cache.

Do these timings for loading /pw/page look reasonable to you?

 

[LostKobrakai]

What's the number of fields/templates?

[adrian]

Actually something interesting to note is how slow the Debug Panel actually is: 262ms. Typically mine shows somewhere between 15 and 35ms. Not sure if that's a contributor on your site, or indicative of the problem.

[dragan]

idk, but I would try to install it on a local Apache environment instead of nginx (AMPPS, Laragon XAMPP, MAMP... what have you)

On 15.3.2018 at 7:01 PM, sodesign said:

does template logic affect load time in the admin?

yes and no. Depending on your page/tpl/field settings, some configs may run faster in page-edit-mode than others (you know, stuff like load only when opening field via AJAX etc. - but that's not TTFB, but mainly the browser needing time to fetch and render all the stuff) - but not the overall speed of moving around in the backend.

If some of your recent changes involved using / adding nested Matrix Repeaters A LOT, then this could be an issue.

 

 

[sodesign]

Just to follow up on this - I bought the Profiler Pro module and have been discussing this in the module forum there.

As part of this I created a test template which just outputs a string, with init.php and main.php prepending disabled - the Profiler Pro time for this is down to under 300ms, while the load time I see in my dev tools is still between 900ms and 3000ms.

My next steps are trying to find out why this discrepancy exists - very strange!

[Lutz]

On 3/16/2018 at 8:56 PM, LostKobrakai said:

What's the number of fields/templates?

Hi LostKobrakai, another example.

PW 3.0.131, 26 templates, 16 fields, on the front-end with Tracy,

Category page with just one field, template file empty:
Execution time 341.5 ms
CPU usage user + system 9 % + 1 %
Peak of allocated memory 14.70 MB
Included files 149
PDO Queries ($database) 57
Selector Queries 7

Article page with 11 fields, template file empty:
Execution time 338.3 ms
CPU usage user + system 11 % + 0 %
Peak of allocated memory 14.40 MB
Included files 149
PDO Queries ($database) 85
Selector Queries 7

(On a dedicated server with 8 GB RAM, PHP 7.2, MySQL 5.7, Apache.) I have no idea what could be done to reduce the number of queries and the CPU and memory usage needed to boot PW. Maybe we could reduce the number of fields, but 16 isn't a big number and it's just a set to start, and it would be difficult to reduce the number of templates.

Of course, that's not a problem with small to medium sized and low traffic websites, but it seems to limit the scalability. And yes, with low traffic and a few million pages this shouldn't be a problem either, or with 1000 pages and high traffic. But I'm not sure how we could use PW with a few million URLs and e.g. 100 page views per second (peak). And I really would be very glad to become more optimistic in this regard.

Apart from the number of fields and templates, are there any other vectors to optimize regarding the server load on boot? Maybe it would be helpful to collect some best practice techniques to improve the scalability of PW besides optimizations of templates or caching.

[LostKobrakai]

The number of fields/templates should only become a problem for like 100+ numbers. 26 and 16 is certainly not in that realm.

[dragan]

Execution time	166.5 ms
CPU usage user + system	20 % + 1 %
Peak of allocated memory	9.55 MB
Included files	230
OPcache	100% cached
Classes + interfaces + traits	238 + 28 + 0
Selector queries	17
HTTP method / response code	GET / 200
PHP	7.2.18
Tracy	2.5.6
Server	Apache/2.4

number of fields in this template: 40 (overall, maybe 70)

Tracy enabled + debug mode on

I would maybe take a look at some server-level optimizations. Or try the same install on another environment.

 

[Lutz]

Thank you LostKobrakai and dragan, I will have a look on a different server. (There's an older ExpressionEngine installation with an earlier version of the site on the same server, showing far less db queries, lower CPU usage and slightly less memory usage on pages with all the EE tags placed, with several loops from different channels and entries relations. So I was surprised to see this results for completely empty templates.)

dragan, how many PDO Queries ($database) did Tracy count?

[Zeka]

@Lutz Heckelmann Not help, but that what I got on the shared hosting 

[Robin S]

Some thoughts...

5 hours ago, Lutz Heckelmann said:

template file empty

What about any auto-prepended _init.php and/or auto-appended _main.php - any code in there that would impact performance?

5 hours ago, Lutz Heckelmann said:

with Tracy

Bear in mind that the PW debug mode and Tracy Debugger have their own memory usage, DB queries, etc. The Tracy overhead in particular could vary a lot depending on what panels are in use. To get a fair comparison across the EE and PW sites on the server you should disable PW debug mode and Tracy and use some consistent performance measurement technique/tool on both sites. 

[Lutz]

@Zeka Wow, 502 PDO queries, thank you. Well, the numbers of database queries shouldn't be the decisive factor, but under certain conditions those higher numbers maybe could become a problem, I fear.

[Lutz]

@Robin S Those results are some with auto-prepend (_init.php) and auto-appended _main.php (both empty), but they were nearly identical without.

Tracy: yes, this especially was my hope, that those additional queries etc. could be a factor. I will continue testing.

[dragan]

34 minutes ago, Lutz Heckelmann said:

dragan, how many PDO Queries ($database) did Tracy count?

180

I'm too tired right now to look at each and every single query, but I'm puzzled by a few randomly spotted queries such as

SELECT false AS isLoaded, pages.templates_id AS templates_id, pages.*, pages_sortfields.sortfield, (SELECT COUNT(*) FROM pages AS children WHERE children.parent_id=pages.id) AS numChildren,field_email.data AS `email__data` 
FROM `pages` 
LEFT JOIN pages_sortfields ON pages_sortfields.pages_id=pages.id 
LEFT JOIN field_email ON field_email.pages_id=pages.id 
WHERE pages.templates_id=3 
AND pages.id IN(40) 
GROUP BY pages.id

I don't need any email field in this page / template. So I wonder why is something like this even queried? I'm sure (or I hope) there's a good reason why this query is listed, but I'm just not sure why. (by Tracy, or PW core? or just PW core-while-in-debug-mode?)

Still - to me, those timings are quite acceptable. And yes, if debug is off, it's even faster. (though I haven't set up a script to measure that - I just look at Google Chrome's performance audit results or similar for TTFB).

[Lutz]

@dragan Many thanks. I think the timings strongly depend on the conditions. Sometimes a large number of pages could be uncached, and I know from experience that peaks (e.g. 60+ page views per second) can change the meaning of overhead enormously.

Maybe it's interesting to have a closer look on all those queries, thanks for the example. I too see queries that I don't understand so far. For example

37	SELECT id, templates_id, parent_id FROM pages WHERE (name=:name) LIMIT 2
38	SELECT id, templates_id, parent_id FROM pages WHERE (name=:name) LIMIT 2
39	SELECT id, templates_id, parent_id FROM pages WHERE (name=:name) LIMIT 2
40	SELECT id, templates_id, parent_id FROM pages WHERE (name=:name) LIMIT 2

or

SELECT false AS isLoaded, pages.templates_id AS templates_id, pages.*, pages_sortfields.sortfield, (SELECT COUNT(*) FROM pages AS children WHERE children.parent_id=pages.id) AS numChildren,field_title.data AS `title__data` FROM `pages` LEFT JOIN pages_sortfields ON pages_sortfields.pages_id=pages.id LEFT JOIN field_title ON field_title.pages_id=pages.id WHERE pages.parent_id=1018 AND pages.templates_id=54 AND pages.id IN(1061) GROUP BY pages.id

 I will have a look at ProfilerPro, maybe it could help to get a better understanding of the boot process.