Spot slow extensions using PHP’s slow log
So what does it do? On average, PHP takes half a second to render a page. When it takes longer than a configured threshold (say, 10 seconds), PHP will record a stack trace and save it to disk for later inspection. Here is an example.
So what is a stack trace?
A stack trace is a snapshot in time of all current active functions, plus their locations in the source code. Because the most specific functions are listed first, you should read a stack trace backwards for a chronological order.
In this example,
rebuildIndex() was called and eventually led to to a number of database
query() calls. At the moment of the trace, the program was busy with the
execute() function in Philwinkle’s DeadlockRetry module.
How to interpret
In this example, one can clearly deduce the bottleneck of this particular slow request. The active module
DeadlockRetry is a subtle ☺ indication of a locked database. Further analysis should involve
mytop to monitor live database behaviour and to view past queries in MySQL’s slow query log.
In our experience of analysing hundreds of Magento shops, these are the three most common causes for slow requests:
- PHP is waiting for database queries to complete. Easily recognized from the function names. Either the database is busy with a large query, or waiting for a lock.
- PHP is waiting for external systems (inventory, supplier, feedback systems). This is easily spotted when the active function is
- PHP is busy running PHP code, for example looping over many products or parsing loads of XML data. This is illustrated when the active function is a PHP function that does not deal with external data.
One should note that the active function or module is not always the source of delay. In the example above, the real cause is a database locking problem started elsewhere, and the DeadlockRetry module is just polling whether the lock has lifted yet.
On Hypernode, the slow PHP log is enabled for you and can be found in
/var/log/php-fpm/php-slow.log. To enable this on your own system, add these lines to the PHP-FPM pool.conf:
slowlog = /var/log/php-fpm/php-slow.log request_slowlog_timeout = 10s
If you have a high-traffic but slow shop, this file will likely contain hundreds of traces. So to extract useful conclusions from this data, some parsing is required. On Hypernode there is a handy utility at your service,
hypernode-fpm-slow-modules which will find non-core Magento extensions in the traces:
$ hypernode-fpm-slow-modules 23-Jun-2016 08:03:03 Fooman_PdfCustomiserPicking 23-Jun-2016 08:12:30 Amasty_Shopby 23-Jun-2016 09:13:14 Mage_Sales 23-Jun-2016 09:15:41 Aschroder_SMTPPro 23-Jun-2016 09:16:38 Mage_Sales 23-Jun-2016 09:18:48 Amasty_Shopby 23-Jun-2016 09:18:48 Nexcessnet_Turpentine 23-Jun-2016 09:18:51 Nexcessnet_Turpentine 23-Jun-2016 09:54:25 Aschroder_SMTPPro 23-Jun-2016 09:58:51 Mage_Sales 23-Jun-2016 09:59:55 Aschroder_SMTPPro 23-Jun-2016 10:25:12 Amasty_Shopby
If this, again, yields a long list, you can produce a summary like this:
$ hypernode-fpm-slow-modules | cut -b22- | sort | uniq -c | sort -nr 51 Aschroder_SMTPPro 43 Mage_Sales 15 Nexcessnet_Turpentine 9 TBT_Rewards 9 Amasty_Shopby 5 WP_CustomMenu 5 Fooman_PdfCustomiser
Here, the Aschroder module caused most slow requests (51). It was probably waiting for a slow SMTP server. Time to switch SMTP servers!
NB. In this example, Mage_Sales looks like a core module but actually is a local override.
The possibility of PHP to automatically produce stack traces for long running requests is little known but very useful. In many cases this will help you to spot a troubled extension or at the very least tell you where to go from here.