• This site uses cookies. By continuing to use this site, you are agreeing to our use of cookies. Learn more.

XF 1.5 How to diagnose slow deferred.php tasks

kontrabass

Well-known member
#1
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:
Screenshot at Sep 07 12-50-18.png

And detail:

Code:
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!
 

Xon

Well-known member
#3
@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

Well-known member
#4
@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

Well-known member
#5
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

Well-known member
#6
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

Well-known member
#7
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.