verbb / navigation

A Craft CMS plugin to create navigation menus for your site.
Other
90 stars 23 forks source link

Node Query is very slow (700ms) #259

Closed nickdunn closed 3 years ago

nickdunn commented 3 years ago

We have a navigation set up with custom/manual entries:

Screenshot 2021-05-14 at 23 09 20

A completely blank Craft page without navigation renders in 295ms with 21 queries:

Screenshot 2021-05-14 at 23 13 41

After adding our node query, and not yet adding any rendering...

{% set nodes = craft.navigation.nodes().handle('pensiontrustees').level(1).with(['children.children.children']).all() %}

Render time jumps to 950ms and 22 queries:

Screenshot 2021-05-14 at 23 14 40

Sorting the Profile table by duration doesn't yield anything longer than 8ms, so the lengthy process isn't captured here.

Adding in our nav rendering adds another 2-300ms which is expected, and we're using eager-loading to keep the queries down:

{% set nodes = craft.navigation.nodes().handle('pensiontrustees').level(1).with(['children.children.children']).all() %}

None of the navigation plugin queries are slow:

Screenshot 2021-05-14 at 23 22 06

If I greedily fetch all 5 of our navigations in one go, the performance hit isn't cumulative — it's only another 50-100ms for each extra Node Query:

{% set nodes1 = craft.navigation.nodes().handle('pensiontrustees').level(1).with(['children.children.children']).all() %}
{% set nodes2 = craft.navigation.nodes().handle('individuals').level(1).with(['children.children.children']).all() %}
{% set nodes3 = craft.navigation.nodes().handle('charities').level(1).with(['children.children.children']).all() %}
{% set nodes4 = craft.navigation.nodes().handle('professionals').level(1).with(['children.children.children']).all() %}
{% set nodes5 = craft.navigation.nodes().handle('individuals').level(1).with(['children.children.children']).all() %}
Screenshot 2021-05-14 at 23 24 55

So it feels like the plugin is doing something else when the first Node Query first runs that's hitting performance?

nickdunn commented 3 years ago

I get the same performance of ~700ms if I strip the navigation back to a single node and use:

{{ craft.navigation.render('pensiontrustees') }}
nickdunn commented 3 years ago

A little more digging. I've gutted my Craft build, deleted all sections, fields and entries. Created a single section and a single entry.

{% set nodes = craft.entries().one() %}

Adds about 25ms to the page load.

{% set nodes = craft.navigation.nodes().handle('pensiontrustees').level(1).all() %}

Adds 500–700ms to the page load.

So I'm pretty sure it's unrelated to site volume (number of entries etc).

nickdunn commented 3 years ago

But if I start from an entirely blank Craft database and just add the plugin, then I get good performance as expected.

So there must be something in my current build that's causing this. I'll continue to tear the database apart.

nickdunn commented 3 years ago

After more debugging I think I'm narrowing this down to a Craft bug. When I make a Node Query it seems that Craft is parsing the config/project directory and YAML files from disk. If I delete this directory then we go back to fast performance.

To your knowledge, Craft shouldn't be parsing these files on frontend template loads, is that right? They're just used in the backend to sync config?

nickdunn commented 3 years ago

I think I have it.

NodeQuery.php

protected function beforePrepare(): bool
    {
        $projectConfig = Craft::$app->getProjectConfig();
        $schemaVersion = $projectConfig->get('plugins.navigation.schemaVersion', true);

This causes Craft to parse the YAML files on disk. I have a large project config, so this is taking a fair chunk of rendering time. Can Navigation fetch this from the database instead?

nickdunn commented 3 years ago

My first thought is to simply purge config/project in my production Docker image since we have allowAdminChanges set to false. But would this cause issues with the above code?

engram-design commented 3 years ago

Thanks for the investigation here! Sounds like it might be slightly specific to your project, but not an uncommon issue - just might've been difficult to replicate on my end.

So really, the only reason for that check is to prevent errors when migrating, as a lot of Craft's own migrations re-save elements. If we include newly added columns in the beforePrepare() function, these will produce an error as Craft re-saves Node elements, because Navigation's own migrations haven't run to add those columns (because Craft's migrations run first).

So really, it's just a safety check I'd be happy to switch to a direct database query. I'd rather this once-off check (before migrations run) not adversely effect general use.

i've just pushed a fix for this in craft-3. My testing on a large-ish site has certainly improved rendering time by at least 60%, which is pretty significant! Interested to see how it goes for you.

To get the fix early, change your verbb/navigation requirement in composer.json to:

"require": {
  "verbb/navigation": "dev-craft-3 as 1.4.16",
  "...": "..."
}

Then run composer update.

nickdunn commented 3 years ago

Nailed it. On my test page that performs a Node Query and nothing else, page load has improved from 1100ms to 340ms. That's almost 70%! I have 258 .yaml files in config/project and I assume this performance hit would only get worse as this number of files increases as the project grows.

Thanks for making a change so quickly over a weekend, really appreciate it.

markhuot commented 3 years ago

This same bug is affecting my site in production as well. We have a rather large project config for a relatively complex site. Switching branches took our first navigation query from 1.2s down to 49ms.

engram-design commented 3 years ago

Well, I'm certainly glad you got to the bottom of that @nickdunn as seeing this consistent across a bunch of sites. I'll keep that in mind for future plugins as well.

Released in 1.4.17