XF 2.1 High server load during theme update

[Recep Baltaş]

When upgrading 3rd party themes, server load goes nuts! Confirmed with two different themes from different devs.

Load Averages: 142.04 122.49 79.36

And it takes more than 10 minutes to upgrade a theme!




There was no such issue with 2.0..

 

[Recep Baltaş]

Every single add-on update kills the server after 2.1..

 

[Kirby]

Do slow queries increase during uprades?
If this is the case InnoDB config might need some love.

 

[Recep Baltaş]

I don't know what you mean by that. What I know is that this was not happening with 2.0. Same config, same DB, except 2.1...

This time it went like this until the DB crashed...

 

[Mike]

I don't believe we've generally changed this process in any material way from 2.0 to 2.1, though it's always possible. It is early days, but we haven't had other general reports of this.

What do your request stats look like during "normal" operation?

If you disable all add-ons, do you get the same behavior with a style import/rebuild?

 

[Recep Baltaş]

What do your request stats look like during "normal" operation?

Server load is around 2.x, even with high load below 10. We've also noticed that even updating a phrase takes a long time now.

If you disable all add-ons, do you get the same behavior with a style import/rebuild?

Didn't try that. I'll wait for the next update I think.

 

[HappyWorld]

I'll wait for the next update I think.

You can rebuild the same version. You don't have to wait for new release.

 

[Recep Baltaş]

You can rebuild the same version. You don't have to wait for new release.

I know but that does not update the code, eh

 

[loulou]

Same issue here under 2.1
Any template or language update make server load go crazy for few minutes.
I thought it was related to page cache, but disabling it did'nt change anyting.

@Recep Baltaş , have you found a solution ?

Regards

 

[Recep Baltaş]

We have removed unused and out of Date add-ons and that did help a lot. Still not as good as 2.0 but nowhere near the first days. Can you list all your add-ons? Via PM if you like.

 

[Recep Baltaş]

This problem is still unresolved after many updates. I really love features of 2.1 but it made the forum a lot slower!

I can't even merge users FFS!

XF\Db\Exception: MySQL query error [1205]: Lock wait timeout exceeded; try restarting transaction in src/XF/Db/AbstractStatement.php at line 217
XF\Db\AbstractStatement->getException() in src/XF/Db/Mysqli/Statement.php at line 196
XF\Db\Mysqli\Statement->getException() in src/XF/Db/Mysqli/Statement.php at line 77
XF\Db\Mysqli\Statement->execute() in src/XF/Db/AbstractAdapter.php at line 94
XF\Db\AbstractAdapter->query() in src/XF/Reaction/AbstractHandler.php at line 141
XF\Reaction\AbstractHandler->updateRecentCacheForUserChange() in src/XF/Service/User/ContentChange.php at line 343
XF\Service\User\ContentChange->stepRebuildReactions() in src/XF/MultiPartRunnerTrait.php at line 48
XF\Service\User\ContentChange->runLoop() in src/XF/Service/User/ContentChange.php at line 198
XF\Service\User\ContentChange->apply() in src/XF/Service/User/Merge.php at line 137
XF\Service\User\Merge->stepReassignContent() in src/XF/MultiPartRunnerTrait.php at line 48
XF\Service\User\Merge->runLoop() in src/XF/Service/User/Merge.php at line 88
XF\Service\User\Merge->merge() in src/XF/Job/UserMerge.php at line 39
XF\Job\UserMerge->run() in src/XF/Job/Manager.php at line 253
XF\Job\Manager->runJobInternal() in src/XF/Job/Manager.php at line 195
XF\Job\Manager->runJobEntry() in src/XF/Job/Manager.php at line 79
XF\Job\Manager->runQueue() in src/XF/Admin/Controller/Tools.php at line 139
XF\Admin\Controller\Tools->actionRunJob() in src/XF/Mvc/Dispatcher.php at line 321
XF\Mvc\Dispatcher->dispatchClass() in src/XF/Mvc/Dispatcher.php at line 244
XF\Mvc\Dispatcher->dispatchFromMatch() in src/XF/Mvc/Dispatcher.php at line 100
XF\Mvc\Dispatcher->dispatchLoop() in src/XF/Mvc/Dispatcher.php at line 50
XF\Mvc\Dispatcher->run() in src/XF/App.php at line 2177
XF\App->run() in src/XF.php at line 390
XF::runApp() in admin.php at line 13

 

[Xon]

On my own site and another large site, I've observed that XF will use massively more CPU during the add-on installs & adding new templates/styles operations above what is expected (that is, every other session not just the admin session doing the changes). With the is_processing flag, these shouldn't be actually running and points to some cache being repeatedly invalidated.

What I did notice was the jobs TemplateRebuild/TemplatePartialCompile (and some others) use the \XF\Service\Template\Compile which updates all styles last modified date, which then invalidates all cached css. This happens per web-request rather than at the end of the template rebuild/compiling jobs. The PhraseRebuild job would be similar.

Add-on install is also impacted, as each template import which rattles around before hitting a template recompile, and then again with template modifications. xf_css_cache is also evacuated immediately, but before the style last modified date is updated, resulting in this table receiving a lot more write traffic than expected.

With batch installing, and complex add-ons, this can result in a large number of requests during the installing phase.

 

[Recep Baltaş]

I still have no idea why a simple user merging gives me a "524 A timeout occurred" error... I use PHP 7.3 and MariaDB 10.3. I don't know what should I do more. There was no such problem with 2.0.

This time, could not even update my theme...

I think I'll create a ticket.

 

[imno007]

Was this issue made even worse by the latest upgrade? Performance was super zippy right after the upgrade and reenabling addon's, but then I started updating the styles and performance took a sudden steep nose-dive.....

 

[Recep Baltaş]

No difference actually. All started with 2.1. BTW, removing Admanager by Siropu did help a lot. Load went from 20 to 3.

 

[imno007]

I was just wondering because this wasn't actually ever a problem for me until this latest update (2.1.3), not that I can recall. And I don't use Admanager, so that definitely wasn't a factor for me. Also, it's a problem for me only when updating styles or saving certain style edits, at least so far.

 

[Recep Baltaş]

What's your PHP version BTW. I use 7.3.

 

[imno007]

Same version. And maybe I spoke too soon about it only being an issue when updating styles, because now all of a sudden the site is timing out - which it definitely was not doing before the update. Guess I know what I'll be spending more time on today....

 

[imno007]

Well, whatever the issue was, it straightened itself out just a couple minutes after I wrote the above, and I don't see anything in the server error logs. I'll keep my fingers crossed!

EDIT: Aah. Still not very familiar with this CyberPanel interface. For whatever reason the error log doesn't show any results from the website dashboard, but from elsewhere I can see a lot of this kind of thing:

2019-07-20 19:53:56.284449 [INFO] [99.230.81.200:55499:HTTP2-35] Pending AIO operation, recycle later...
2019-07-20 19:53:56.284472 [INFO] Pending AIO finished, recycle connection.
2019-07-20 19:53:57.784773 [NOTICE] [25129] Cmd from child: [extappkill:8558:-3]
2019-07-20 19:53:57.784793 [INFO] [CLEANUP] Send signal: 15 to process: 8558
2019-07-20 19:53:57.784715 [INFO] [99.230.81.200:55499:HTTP2-37] Abort request processing by PID:8558, kill: 1, begin time: 1, sent time: 1, req processed: 0
2019-07-20 19:53:57.784737 [NOTICE] [25137] sendKillCmdToWatchdog: 'extappkill:8558:-3'.
2019-07-20 20:10:22.755383 [NOTICE] [25129] Cmd from child: [extappkill:9343:-3]
2019-07-20 20:10:22.755407 [INFO] [CLEANUP] Send signal: 15 to process: 9343
2019-07-20 20:10:22.755420 [NOTICE] [25129] Cmd from child: [extappkill:9345:-3]
2019-07-20 20:10:22.755425 [INFO] [CLEANUP] Send signal: 15 to process: 9345
2019-07-20 20:10:22.754993 [INFO] [162.239.232.190:7122:HTTP2-47] Abort request processing by PID:9343, kill: 1, begin time: 0, sent time: 0, req processed: 1
2019-07-20 20:10:22.755011 [NOTICE] [25137] sendKillCmdToWatchdog: 'extappkill:9343:-3'.
2019-07-20 20:10:22.755345 [INFO] [162.239.232.190:7122:HTTP2-49] Abort request processing by PID:9345, kill: 1, begin time: 0, sent time: 0, req processed: 1
2019-07-20 20:10:22.755348 [NOTICE] [25137] sendKillCmdToWatchdog: 'extappkill:9345:-3'.
2019-07-20 20:15:49.916024 [NOTICE] [25129] Cmd from child: [extappkill:10082:-3]
2019-07-20 20:15:49.916046 [INFO] [CLEANUP] Send signal: 15 to process: 10082
2019-07-20 20:15:49.915926 [INFO] [162.239.232.190:7599:HTTP2-39] Abort request processing by PID:10082, kill: 1, begin time: 1, sent time: 1, req processed: 1
2019-07-20 20:15:49.915942 [NOTICE] [25137] sendKillCmdToWatchdog: 'extappkill:10082:-3'.
2019-07-20 20:15:50.105202 [NOTICE] [25129] Cmd from child: [extappkill:10089:-3]
2019-07-20 20:15:50.105214 [INFO] [CLEANUP] Send signal: 15 to process: 10089
2019-07-20 20:15:50.105111 [INFO] [162.239.232.190:7599:HTTP2-45] Abort request processing by PID:10089, kill: 1, begin time: 0, sent time: 0, req processed: 0
2019-07-20 20:15:50.105126 [NOTICE] [25137] sendKillCmdToWatchdog: 'extappkill:10089:-3'.
2019-07-20 20:18:41.578111 [NOTICE] [25129] Cmd from child: [extappkill:10290:-3]
2019-07-20 20:18:41.578139 [INFO] [CLEANUP] Send signal: 15 to process: 10290
2019-07-20 20:18:41.578158 [NOTICE] [25129] Cmd from child: [extappkill:10292:-3]
2019-07-20 20:18:41.578166 [INFO] [CLEANUP] Send signal: 15 to process: 10292
2019-07-20 20:18:41.578019 [INFO] [162.239.232.190:7888:HTTP2-17] Abort request processing by PID:10290, kill: 1, begin time: 0, sent time: 0, req processed: 1
2019-07-20 20:18:41.578040 [NOTICE] [25137] sendKillCmdToWatchdog: 'extappkill:10290:-3'.
2019-07-20 20:18:41.578123 [INFO] [162.239.232.190:7888:HTTP2-19] Abort request processing by PID:10292, kill: 1, begin time: 0, sent time: 0, req processed: 0
2019-07-20 20:18:41.578125 [NOTICE] [25137] sendKillCmdToWatchdog: 'extappkill:10292:-3'.
2019-07-20 20:25:33.687315 [NOTICE] [25129] Cmd from child: [extappkill:10810:-3]
2019-07-20 20:25:33.687337 [INFO] [CLEANUP] Send signal: 15 to process: 10810
2019-07-20 20:25:33.690277 [NOTICE] [25129] Cmd from child: [extappkill:10813:-3]
2019-07-20 20:25:33.690292 [INFO] [CLEANUP] Send signal: 15 to process: 10813
2019-07-20 20:25:33.687225 [INFO] [162.239.232.190:8416:HTTP2-19] Abort request processing by PID:10810, kill: 1, begin time: 0, sent time: 0, req processed: 1
2019-07-20 20:25:33.687241 [NOTICE] [25137] sendKillCmdToWatchdog: 'extappkill:10810:-3'.
2019-07-20 20:25:33.690209 [INFO] [162.239.232.190:8416:HTTP2-21] Abort request processing by PID:10813, kill: 1, begin time: 0, sent time: 0, req processed: 0
2019-07-20 20:25:33.690213 [NOTICE] [25137] sendKillCmdToWatchdog: 'extappkill:10813:-3'.
2019-07-20 20:28:32.923175 [NOTICE] [25129] Cmd from child: [extappkill:11060:-3]
2019-07-20 20:28:32.923204 [INFO] [CLEANUP] Send signal: 15 to process: 11060
2019-07-20 20:28:32.922891 [INFO] [162.239.232.190:8677:HTTP2-17] Abort request processing by PID:11060, kill: 1, begin time: 0, sent time: 0, req processed: 2
2019-07-20 20:28:32.922920 [NOTICE] [25137] sendKillCmdToWatchdog: 'extappkill:11060:-3'.
2019-07-20 20:30:04.963192 [NOTICE] [25129] Cmd from child: [extappkill:11195:-3]
2019-07-20 20:30:04.963213 [INFO] [CLEANUP] Send signal: 15 to process: 11195
2019-07-20 20:30:04.963226 [NOTICE] [25129] Cmd from child: [extappkill:11198:-3]
2019-07-20 20:30:04.963231 [INFO] [CLEANUP] Send signal: 15 to process: 11198
2019-07-20 20:30:04.963044 [INFO] [162.239.232.190:8677:HTTP2-55] Abort request processing by PID:11195, kill: 1, begin time: 0, sent time: 0, req processed: 1
2019-07-20 20:30:04.963073 [NOTICE] [25137] sendKillCmdToWatchdog: 'extappkill:11195:-3'.
2019-07-20 20:30:04.963149 [INFO] [162.239.232.190:8677:HTTP2-57] Abort request processing by PID:11198, kill: 1, begin time: 0, sent time: 0, req processed: 0
2019-07-20 20:30:04.963151 [NOTICE] [25137] sendKillCmdToWatchdog: 'extappkill:11198:-3'.

 

[Recep Baltaş]

I have no idea either. I use cPanel