Strange slowing down of Tracy's Processwire Info reading on a specific host environment

[iank]

Hi @adrian,

I'm unsure what's going on here but for a while now on a specific host (it's a cPanel server) I've been experiencing severe slowdowns when Tracy is enabled and it seems to be related to the reading of the Processwire logs  Info.   It's a bit like the old problem from 2022 when reasonable numbers of logs / large log files were slowing the page loading down when the debug bar was enabled. 

The odd thing is, I don't have the same problem on my local dev environment, or indeed on a different host, so I'm not sure where to look to troubleshoot.

The environment in question is:

PW 3.0.200-3.0.229 (various sites with different PW versions)
PHP 8.1.32
MySQL Server: 10.6.22-MariaDB

Sometimes, depending on the site and the number of log files, it can take up to 45 seconds to load, even though I've disabled the Processwire Logs panel:

Whereas the same site (with the same log files) on my dev environment (and similar sites hosted elsewhere) are fine, even with the PW logs panel enabled:

So I'm thinking it's some setting on the server - perhaps something like Imunify360 - could this be scanning the log files every time they're loaded and that's  what's slowing it down? 

If I disable Tracy entirely, the same pages load happily in milliseconds, so it's some combination of Tracy and this specific server environment.

I tried to disable the Processwire logs (as per the first screenshot above) but that only seems to work for a minute or so, and then the long loading time reappears. 

Hoping you can point me in some direction to narrow this down.. 🙏

Thanks,
Ian.

Edited June 26 by iank
Changed logs to info after pinning down the cause

[iank]

3 minutes ago, iank said:

So I'm thinking it's some setting on the server - perhaps something like Imunify360 - could this be scanning the log files every time they're loaded and that's  what's slowing it down?

.. Though I don't believe this is the issue - with Tracy disabled, loading the PW Setup=>Logs overview page is pretty much instant...

[adrian]

Hi @iank - that first screenshot is confusing me because if the PW Logs panel is disabled, it shouldn't load at all and you shouldn't see any ms/kb values. I am not really sure what you mean by "only seems to work for a minute or so, and then the long loading time reappears" - if you're using the "sticky" option to disable it, then it should remain disabled until cookies are cleared, but even if that happens, the checkbox next to it would be checked. I can't see a way for the ms/km to be there with the checkbox unchecked (after sticky has been clicked).

As for the actual slowdown - you mention that the log files on dev are the same - are they the same size as well?

How large are the log files - can you check through and let me know the largest one.

Are you loading just the default last 100 lines?

It's also worth noting that Tracy caches the lines from the log files so it should only ever read them if their modified timestamp has changed since the last load.

Let me know those things and we'll go from there.

[iank]

Hey @adrian,

Thanks for the quick response!  In answer to your questions:

11 minutes ago, adrian said:

if you're using the "sticky" option to disable it, then it should remain disabled until cookies are cleared, but even if that happens, the checkbox next to it would be checked. I can't see a way for the ms/km to be there with the checkbox unchecked (after sticky has been clicked).

Yes, that's what confused me as well - I thought unchecking the box and choosing 'sticky' would completely disable it, but after a minute or two (presumably after one or more of the files gets updated) the page slows down again and the ms/kb notification reappears, even though the box is still unchecked.  This is reproducible.  

Some of my sites are quite busy so the logfiles are getting modified frequently.

10 minutes ago, adrian said:

you mention that the log files on dev are the same - are they the same size as well?

Yes, I copied the logfiles down to the dev so they'd be exactly the same in number and in size.

17 minutes ago, adrian said:

How large are the log files - can you check through and let me know the largest one.

The largest is 1.6Mb.  There are quite a few logs (78 to be exact - though many of those are empty - I have a Cron job that prunes them to 30 days each night).  Total size of all files is 6.1Mb.

However, I deleted all the log files a short while ago to see what effect that would have - now there are only 11 that have been recreated since I did that - totalling 9.7kb.  I've just gone back into the admin and the page took over 45 seconds to load, showing the counts even though that checkbox is 'sticky unchecked'!:

 

24 minutes ago, adrian said:

Are you loading just the default last 100 lines?

No, in fact I'd reduced this to 10 lines to see if that would help.

24 minutes ago, adrian said:

It's also worth noting that Tracy caches the lines from the log files so it should only ever read them if their modified timestamp has changed since the last load.

Ah, yes - that would probably explain why things seem quick again for a minute or two and then slow down. 

Thanks for all your help!

Ian.

 

[iank]

What's also interesting is that the Tracy Bar shows just a few hundred ms loading time, even though the page took 45s to load:

[adrian]

Thanks for all those details - helps to narrow things down a bit - it's certainly not an issue with the size or number of log files.

I still don't know why you're having the slow loading or why the ms/kb is showing when the panel isn't loaded - I'd be curious if there is a difference if the panel is disabled permamently from Tracy's settings.

One thing I did just find and fix was the caching - it wasn't actually working as intended. I still don't think it will help with your slow loading, but worth checking to see if it also has any impact on the ms/kb populating when the panel is disabled - it shouldn't but who knows 😖

 

[iank]

OK, so here's a turn up for the books  - it's not the Processwire logs panel that's the issue - it's the Processwire Info panel!  

I noticed that the ms/kb count on one page refresh seemed to be next to the Processwire Info, so I turned that off and bingo!  Everything loads consistently in milliseconds!

Even with the logs panel turned back on, the pages are loading really quickly.   I think it's somehow a misplacement of the counts and they're ending up next to the wrong checkbox.

I've been through some of my other sites on that server, all exhibiting the same issue; turned off Processwire Info and  - consistent millisecond loading across all those sites. 

And here's a screenshot of one of them that might show the misplacement better (before I toggled the Info panel off):

I think it's the ProcessWire Info here that's taking 17 seconds.  

So - I don't know why that should be, but at least that's something to work with 🙂 

Regards,
Ian.

[adrian]

Thanks for figuring that out. At least the logs rabbit hole made me notice an issue with its caching which is great :)

Now for the reason for the Info panel - can you please go through Tracy's settings for the panel and figure out which of its sections are causing the slowdown - I can only think it's the Versions List and something on the server taking a long time to return something within that.

I can replicate the misalignment issue when the ms is really long like that, so I'll take a look at fixing that.

[adrian]

@iank - just committed a new version with a revamped panel selector - now uses a table and fixes those wrapping / alignment issues. Hopefully this will prevent future confusion as to what panel is having issues.

[iank]

Hi @adrian,

Many thanks.  I think your suspicions are correct. It looks like the Versions info that's causing the problem.  I presume there's some caching going on here too?  If I refresh the page within a few seconds, it loads fairly quickly, but if I leave it for a few minutes, I get the long delay and large ms count on the next page view.  This is with everything disabled in Processwire Info except Versions Info.

I wonder if it's something to do with the mySQL server version query? There have been a couple of mySQL updates in recent weeks/months and it certainly didn't used to behave like this.

Cheers,
Ian.

[adrian]

I don't actually cache anything for this panel - never seen any performance issues before, but perhaps PHP's OpCache is?

Perhaps you would be willing to debug which component is the issue?

These are the lines that populate the various versions. You could start by commenting out the MySQL ones, then the server settings, then apache modules, etc.

https://github.com/adrianbj/TracyDebugger/blob/5e5d483a7f4d30c4e3f52c40921897a4603b6151/panels/ProcesswireInfoPanel.php#L205-L292

 

 

[iank]

Happy to, Adrian, though it will be tomorrow now. It's nearly midnight now here in Blighty! 😴

[iank]

Hi @adrian,

I've now narrowed it down to a couple of elements in the panel code.  The main one is the Imagick code, which seems to be the one that creates the 45s delay if you don't visit a page for 5 minutes or so.  

https://github.com/adrianbj/TracyDebugger/blob/5e5d483a7f4d30c4e3f52c40921897a4603b6151/panels/ProcesswireInfoPanel.php#L264-L278

There's also some slowdown on the Apache modules section, though this varies and I can't quite put my finger on it, but sometimes takes a few seconds:

https://github.com/adrianbj/TracyDebugger/blob/5e5d483a7f4d30c4e3f52c40921897a4603b6151/panels/ProcesswireInfoPanel.php#L230-L250

I commented both those sections out and re-enabled the ProcessWire Info panel and all its subsections (and the Logs panel) and pages are now loading reliably in less than 200ms. 👍

I don't know if there's anything you can (or should) do about this, given the highly specific nature of this environment, but at least I now have a workaround and can troubleshoot again without going for a cup of tea while the page loads!

I'm happy to continue with further checks for you if necessary.

Many thanks,
Ian.

[adrian]

Thanks @iank - could you let me know what version of PHP and imagemagick and imagick you are running?

Could you also figure out if it's queryformats() or getVersion() that is the main culprit.

Thanks.

[iank]

Hi @adrian,

It appears to be mainly queryformats() that's the culprit - this is taking 40-odd seconds when first run after a few minutes idle time ; though if I run getVersion() first (similarly after some idle time) the latter can take 20s or so. 

Most of the sites are running PHP 8.1.32 and the Imagick version details are as follows:

Thanks,
Ian.

[adrian]

Thanks @iank - curious if you have Ghostscript installed - I do and don't have any issues, but some of the reading I am just done suggests it can contribute. The other thing that comes up is a missing or misconfigured font paths (e.g., /etc/fonts/fonts.conf)

I did also read that IM6 is slower at this than IM7, but I am also running 6 without issues, so who knows :)

Otherwise, I am really not sure at this point. I'd love to hear if anyone else has the same issue. It's possible to use an exec call to IM's convert but I didn't take that route because on some servers exec can be disabled. Maybe the best option for you is to just disable the Versions List unless we hear others having the same problems.

 

[iank]

Hi @adrian,

No, I don't have Ghostscript installed; and I'm not sure about the fonts path thing - I'm no server expert..

I agree - I don't think it's worth you spending any more time on this unless other people report similar issues.  I have a good workaround thanks to your input, so that's very much appreciated.

Maybe I should rename the title of this post, given that we eliminated the logs panel as the source of the issue?

 

[adrian]

2 minutes ago, iank said:

Maybe I should rename the title of this post, given that we eliminated the logs panel as the source of the issue?

Yeah, might be worth a strikethru of the "logs" and add "info" so it isn't too confusing when reading through, but also points to the exact issue in the title.