Articles

How to Read the PHP Slow Request Log

The PHP slow request log is where PHP records information about any request that takes more than five seconds to execute.

Having slow PHP code not only creates a bad experience for your site's visitors, but it is also expensive for you. An app with fast PHP code only needs a single PHP process to handle many requests each second. However, since each PHP process can only execute one request at a time, when a PHP script is slow, the app needs additional PHP processes to handle the requests. Each additional process uses more memory, so having slow code means your server needs a lot more memory.

If your server has high memory usage or requests that are timing out, you may have slow requests that you can debug by reading the PHP slow request log.

Location of the PHP Slow Request Log

On the ServerPilot Business plan, you can view the PHP slow request log from each app's Logs tab in ServerPilot.

If you're not on the Business plan, you can SSH or SFTP into your server to view the PHP slow request log.

Each app has its own PHP slow request log. The log file is located under the app's system user's home directory at:

log/APPNAME/APPNAME_phpX.Y.slow.log

where phpX.Y is the PHP version the app is using, for example php7.0.

Understanding the PHP Slow Request Log

The PHP slow request log records stack traces (also known as tracebacks) of each slowly executing script at the moment the request passed five seconds in execution.

For example, an entry in the slow request log might look like this:

[06-Oct-2015 12:20:34]  [pool example] pid 1852
script_filename = /srv/users/serverpilot/apps/example/public/index.php
[0x00007f7e475ba138] curl_exec() /srv/users/serverpilot/apps/example/public/wp-content/plugins/wp-piwik/classes/WP_Piwik/Request/Rest.php:44
[0x00007f7e475b9f10] curl() /srv/users/serverpilot/apps/example/public/wp-content/plugins/wp-piwik/classes/WP_Piwik/Request/Rest.php:20
[0x00007f7e475b9d48] request() /srv/users/serverpilot/apps/example/public/wp-content/plugins/wp-piwik/classes/WP_Piwik/Request.php:63
[0x00007f7e475b9be0] perform() /srv/users/serverpilot/apps/example/public/wp-content/plugins/wp-piwik/classes/WP_Piwik.php:941
[0x00007f7e475b99f8] request() /srv/users/serverpilot/apps/example/public/wp-content/plugins/wp-piwik/classes/WP_Piwik.php:1098
[0x00007f7e475b98b8] updateTrackingCode() /srv/users/serverpilot/apps/example/public/wp-content/plugins/wp-piwik/classes/WP_Piwik/TrackingCode.php:16
[0x00007f7e475b9720] __construct() /srv/users/serverpilot/apps/example/public/wp-content/plugins/wp-piwik/classes/WP_Piwik.php:288
[0x00007fffa8cdcac0] addJavascriptCode() unknown:0
[0x00007f7e475b9540] call_user_func_array() /srv/users/serverpilot/apps/example/public/wp-includes/plugin.php:503
[0x00007f7e475b9428] do_action() /srv/users/serverpilot/apps/example/public/wp-includes/general-template.php:2284
[0x00007f7e475b9358] wp_footer() /srv/users/serverpilot/apps/example/public/wp-content/themes/k2/footer.php:17
[0x00007f7e475b9358] +++ dump failed

The first two lines tell you the time of the slow request and which script was initially requested. In the above example, these first two lines are:

[06-Oct-2015 12:20:34]  [pool example] pid 1852
script_filename = /srv/users/serverpilot/apps/example/public/index.php

The third line (the line immediately below the first two lines) is the top of the stack trace. This tells you the currently executing function at the time the script passed five seconds in execution. In the example above, the top of the stack trace is:

[0x00007f7e475ba138] curl_exec() /srv/users/serverpilot/apps/example/public/wp-content/plugins/wp-piwik/classes/WP_Piwik/Request/Rest.php:44

The three parts of this line are a unique identifier for the request ([0x00007f7e475ba138]), the name of the executing function (curl_exec()), and the file name and line number of that function (/srv/users/.../Request/Rest.php:44).

The top of the stack trace is generally the cause of your script's slowness. The rest of the lines below that tell you each function call that led up to that point.

Note that you will sometimes see +++ dump failed at the bottom of a stack trace. That indicates the end of the stack trace and does not indicate a problem.

If you see a WordPress plugin name in the slow request log, you may be able to resolve your app's slow request problems by disabling the plugin.

Common Causes of Slow Requests

There are a few common causes of slow requests.

Slow Requests Due to curl_exec()

If you see the curl_exec() function in your PHP slow request log, the problem is not a bug in cURL but rather that the request is taking a long time to complete.

When your scripts rely on making requests to external services and other websites, your own site can become slow and unreliable due to problems with the other website. For example, if their website is slow or is rate-limiting your requests, your own app will become very slow. These issues can be resolved by disabling plugins that make external requests and not writing your own PHP code to perform HTTP requests to external websites or services.

Slow Requests Due to mysqli_query()

If you see the mysqli_query() function in your PHP slow request log, the problem is not a bug in MySQL or any MySQL settings but rather that your PHP code is executing slow SQL queries.

You can have slow SQL queries due to, for example, lack of proper indexes in your database tables or PHP code that is inefficiently using the databases. The solution in this case is to track down the particular queries that are slow and fix them.

Acceptable Cases of Slow Requests

There is one acceptable case of slow requests where you can safely ignore entries in the PHP slow request log: slow requests that are not being performed when answering a website visitor's request but rather are scheduled requests being performed in the background. Common example of such requests are requests for wp-cron.php or any requests you may have scheduled using cron.