Jump to content

Large log file(s) slowing entire site down

teppo

By teppo,
in Tracy Debugger

 Share

Recommended Posts

teppo Hero Member

teppo

Posted
Posted

Hey Adrian (and others, in case anyone else happens to run into this issue)!

I'm posting here instead of opening a GitHub issue since this doesn't feel like a "bug" or "issue", but rather "a potential gotcha":

The background is that I've been recently dealing with major performance issues at weekly.pw. Every request was taking 10+ seconds, which made editing content... let's say an interesting experience. Particularly when PW triggers additional HTTP requests for a number of things, from checking if a page exists to the link editor modal window. Makes one think twice before clicking or hovering over anything in the admin... ?

I've tried to debug the issue with little luck, eventually deciding to blame it on the server (sorry, Contabo!) until today — accidentally, while migrating the site to a new server — finally figured out that the real problem was in fact the Tracy Logs panel and a ~800M, ~3.5 million row logs/tracy/error.log file. The underlying reason for this were warnings generated by the XML sitemap module: each request was generating ~2.5k new rows, with an hour long cache, so potentially 60k or more new rows per day.

Now, I'm writing this half hoping that if someone else runs into similar problem they'll be smarter than me and check if any of the Tracy panels suffer from slow rendering time (which is already reported for each panel individually), but I do also wonder if there's something that could automatically prevent this? Perhaps logs should be pruned, Tracy should warn if there's crazy amount of data in one of the log files, or log file reading could be somehow optimized?

Food for thought. Again this is obviously not a bug, but still something that can end up biting you pretty hard ?

  • Like 4
Link to comment
Share on other sites
adrian Hero Member

adrian

Posted
Posted

Hi @teppo - I have come across this a couple of times before so I would like to give it some attention. Tracy uses PW's $log->getEntries() method to get the last lines from each log file. I have been thinking about implementing a custom solution. There is an excellent writeup here: https://stackoverflow.com/questions/15025875/what-is-the-best-way-to-read-last-lines-i-e-tail-from-a-file-using-php

I wonder if I should implement into Tracy or whether we should try to get a more performant solution in the PW core. Tracy caches log file entries, but if a file changes that benefit is lost and because the log files are loaded on every page load with Tracy, so it's obviously much more important than in the PW core.

Any thoughts?

Link to comment
Share on other sites
adrian Hero Member

adrian

Posted
Posted

Another update - my new version is faster at parsing the log files and get the last number of lines required, but it turns out that the biggest slowdown in the entire process is generating the code editor link which is added to the "Text" column. The reason is that because we're only loading the last 10 lines of the file, I was having to get the total number of lines in the file to figure out what line number the entry is actually on. I think given the potential impact on performance I should remove the link.

Any thoughts?

Link to comment
Share on other sites
teppo Hero Member

teppo

Posted
  • Author
Posted
12 hours ago, adrian said:

Ok, new version removes the line number and I also implement a faster way of getting the last lines from the log files. Should be a LOT faster now with large log files.

@teppo - can you please confirm at your end?

 Confirmed.

Added some extra lines to the log to make sure, and rendering the Tracy Logs panel went from 16863.97 ms to 5.2 ms. A lot faster indeed ?

  • Like 1
Link to comment
Share on other sites
teppo Hero Member

teppo

Posted
  • Author
Posted

To be fair it was largely my own fault for letting the log file blow up. Anyway, a splendid performance boost ?

14 hours ago, netcarver said:

@teppo Maybe Soma's LogMaintenance module would be useful?

Interestingly I had this module installed. Might've been a configuration error or something; should probably give it another try ?

Link to comment
Share on other sites
teppo Hero Member

teppo

Posted
  • Author
Posted
1 hour ago, kongondo said:

@teppo Do you know if this was affecting the frontend as well. weekly.pw has in the recent past been quite slow to load for me. I've just checked now and it loads very fast.

Likely yes.

I did notice as well that requests that missed the (Cloudflare) cache seemed sluggish. The server was struggling under the load, so even requests served via ProCache were unusually slow.

Link to comment
Share on other sites
gmclelland Hero Member

gmclelland

Posted
Posted

Just tried the update.  Unfortunately, I'm seeing some errors in Tracy's Processwire Logs Panel that I thought I should report.

Spoiler 
ErrorException: mb_convert_encoding() expects parameter 1 to be string, array given in /Users/glenn/websites/mywebsite/wwwroot/site/assets/cache/FileCompiler/site/modules/TracyDebugger/panels/ProcesswireLogsPanel.php:52
Stack trace:
#0 [internal function]: Tracy\Bar->Tracy\{closure}(2, 'mb_convert_enco...', '/Users/glenn/we...', 52, Array)
#1 /Users/glenn/websites/mywebsite/wwwroot/site/assets/cache/FileCompiler/site/modules/TracyDebugger/panels/ProcesswireLogsPanel.php(52): mb_convert_encoding(Array, 'UTF-8')
#2 /Users/glenn/websites/mywebsite/wwwroot/site/assets/cache/FileCompiler/site/modules/TracyDebugger/tracy-2.7.x/src/Tracy/Bar/Bar.php(149): ProcesswireLogsPanel->getTab()
#3 /Users/glenn/websites/mywebsite/wwwroot/site/assets/cache/FileCompiler/site/modules/TracyDebugger/tracy-2.7.x/src/Tracy/Bar/Bar.php(122): Tracy\Bar->renderPanels('')
#4 /Users/glenn/websites/mywebsite/wwwroot/site/assets/cache/FileCompiler/site/modules/TracyDebugger/tracy-2.7.x/src/Tracy/Bar/Bar.php(98): Tracy\Bar->renderHtml('main')
#5 /Users/glenn/websites/mywebsite/wwwroot/site/assets/cache/FileCompiler/site/modules/TracyDebugger/tracy-2.7.x/src/Tracy/Debugger/Debugger.php(296): Tracy\Bar->render()
#6 [internal function]: Tracy\Debugger::shutdownHandler()
#7 {main}

 

Saving Tracy's settings page, clearing the compiled files and refreshing the modules didn't seem to help.

  • Like 1
Link to comment
Share on other sites
adrian Hero Member

adrian

Posted
Posted

@gmclelland - it looks like the option to parse an array was only made available since PHP 7.2 - "This function now also accepts an array as string. Formerly, only strings have been supported."

This is something I actually introduced back in December (I guess you haven't updated since then).

Anyway, I've moved that call earlier onto the main string (before I break it into an array) which I think should have the same affect without breaking in older PHP versions.

Can you please try the latest version and let me know?

Link to comment
Share on other sites
teppo Hero Member

teppo

Posted
  • Author
Posted
On 2/6/2022 at 6:49 PM, adrian said:

I hope not - none of Tracy's panels should be loaded on the frontend of a site unless the debug bar is enabled (Tracy is in development mode) which should only happen for an authorized user (usually only superusers).

You're right (of course). Just double-checked with earlier Tracy version, and no slow-downs for non-authenticated requests.

Could've been an indirect result, i.e. my authenticated requests might've slowed entire server down considerably, which in turn would result in visible delays for others. Other than that... no idea, but things seem to be working well now ?

  • Like 2
Link to comment
Share on other sites

Create an account or sign in to comment

You need to be a member in order to leave a comment

Create an account

Sign up for a new account in our community. It's easy!

Register a new account

Sign in

Already have an account? Sign in here.

Sign In Now
 Share
Go to topic listing

  • Recently Browsing   0 members

    • No registered users viewing this page.
×
×
  • Create New...