XF 1.5 How to diagnose slow deferred.php tasks

[kontrabass]

Hi!

I installed an addon by Xon that tracks slow queries, and I have found a correlation between a bunch of slow deferred.php queries and my forum going down for about 20 seconds.

Here are the slow queries that caused the latest outage:


And detail:

Error Info Exception: Slow query detected: 13.7503 seconds, /deferred.php - library/SV/SlowQueryLogger/Profiler.php:126
Generated By: Unknown Account, 6 minutes ago
Stack Trace #0 /home/talkbass/html/library/Zend/Db/Statement.php(319): SV_SlowQueryLogger_Profiler->queryEnd(0)
#1 /home/talkbass/html/library/Zend/Db/Adapter/Abstract.php(479): Zend_Db_Statement->execute(Array)
#2 /home/talkbass/html/library/XenForo/Model/DataRegistry.php(164): Zend_Db_Adapter_Abstract->query('\r\n\t\t\tINSERT INT...', Array)
#3 /home/talkbass/html/library/XenForo/Model/Deferred.php(188): XenForo_Model_DataRegistry->set('deferredRun', 1504806321)
#4 /home/talkbass/html/deferred.php(21): XenForo_Model_Deferred->setNextDeferredTime(1504806321)
#5 {main}Request State array(3) {
  ["url"] => string(37) "https://www.talkbass.com/deferred.php"
  ["_GET"] => array(0) {
  }
  ["_POST"] => array(3) {
    ["_xfRequestUri"] => string(27) "/forums/luthiers-corner.57/"
    ["_xfNoRedirect"] => string(1) "1"
    ["_xfResponseType"] => string(4) "json"
  }
}

I'm wondering if anyone can give me insight into what exactly is being done here, and if there's anything I can do to optimize it.

Thanks!

 

[rdn]

Do you have this addon installed?
https://theadminzone.com/resources/...h-notifications-now-with-simple-install.1069/

It's the most CPU/Mysql/PHP intensive addon I have.
Had to disable it for now to avoid deadlocks and lock timeout error.
Having 140K subscribers now.

 

[Xon]

@kontrabass are you using VMs? These are slow insert/update to what is a single row, there should be no reason why it is basically blocking for so long.

My first feeling is do you have monitoring checking for CPU steal. Spikes higher than 10% will cause you pain.

The alternative is you have an add-on which writes to that row/column in a long transaction. (ie @RoldanLT's idea)

 

[kontrabass]

@kontrabass are you using VMs? These are slow insert/update to what is a single row, there should be no reason why it is basically blocking for so long.

My first feeling is do you have monitoring checking for CPU steal. Spikes higher than 10% will cause you pain.

The alternative is you have an add-on which writes to that row/column in a long transaction. (ie @RoldanLT's idea)

Virtual machines? No, we have a dedicated web box and dedicated db box, both with robust hardware with SSD's.

So must be an add-on, though I'm not sure how to figure out which one... should I be looking at a mysql slow query log? Thanks for your help!

 

[Xon]

Slow queries due to transactions are not fun to track down. I recommend checking the MySQL slow query log to see if you are having large amounts of "lock" time vs "executing" time.

If so, OneSignal doing outbound API calls in a transaction can definitely be a major contributing factor. But this is something you'll need to talk with the add-on author to fix the performance issues.

 

[kontrabass]

Hi Xon,

Thanks for your help here. I think I've found the culprit, that being slow external lookup caused by a mobile app addon. (We don't use OneSignal).

 

[Xon]

Thanks for your help here. I think I've found the culprit, that being slow external lookup caused by a mobile app addon. (We don't use OneSignal).

Yeah, external calls are easy to mess up. Especially if they are done inside a transaction, as the rule of thumb is don't do long blocking actions inside transactions or your database will be sad.