How to log and fix slow PHP requests

When troubleshooting a slow PHP website, logging slow requests is very important.

The most common way to run a PHP website is via PHP-FPM, and, surprise, it has some directives for the job of logging slow requests.

How to enable PHP-FPM slow log

PHP-FPM slow log can be configured on a per pool basis, which means you can configure for a specific website when you need to troubleshoot performance issues.
Simply edit the PHP-FPM pool configuration, e.g. /etc/php-fpm.d/example.com.conf and add directives specifying the desired location of the slow log file and the time it takes for a script to run for it to be logged:

slowlog = /srv/www/example.com/logs/slow.log
request_slowlog_timeout = 3s

The slowlog directive is the path to a file where the slow requests will be logged. Of course, the path to the slow log file should be somewhere that the PHP-FPM pool user can create/read/write files.

The request_slowlog_timeout is the time after which PHP-FPM will dump a backtrace for slow requests. 3 seconds is a good starting point where a script can be deemed as slow.
Although I’d really think of any script that takes more than one second to be slow, we should account for under-powered servers.

That’s pretty much all it takes for configuring it. Simply run systemctl reload php-fpm to apply the configuration, and slow requests will be logged going forward.

Working with the PHP-FPM slow log files

Each slow request, exceeding in time than the configured threshold will be logged as an entry containing the date, pool ID, the script_filename, and the backtrace of the recent function calls.
Example:

[05-Jun-2020 12:16:43]  [pool example.com] pid 19995
script_filename = /srv/www/example.com/httpdocs/wp-admin/index.php
[0x00007f53de01d7d0] curl_exec() /srv/www/example.com/httpdocs/wp-includes/Requests/Transport/cURL.php:162
[0x00007f53de01d710] request() /srv/www/example.com/httpdocs/wp-includes/class-requests.php:379
[0x00007f53de01d610] request() /srv/www/example.com/httpdocs/wp-includes/class-http.php:394
[0x00007f53de01d480] request() /srv/www/example.com/httpdocs/wp-includes/class-http.php:611
[0x00007f53de01d3e0] post() /srv/www/example.com/httpdocs/wp-includes/http.php:181
[0x00007f53de01d350] wp_remote_post() /srv/www/example.com/httpdocs/wp-admin/includes/dashboard.php:1687
[0x00007f53de01d270] wp_check_browser_version() /srv/www/example.com/httpdocs/wp-admin/includes/dashboard.php:27
[0x00007f53de01d120] wp_dashboard_setup() /srv/www/example.com/httpdocs/wp-admin/index.php:15

The slow log entries, unfortunately, only include script_filename and not the URI that is being called.
So you can’t look at the slow log alone to get complete information about the slow request, because in most front-controller pattern frameworks (which WordPress is),
there will be mostly a single, or in some cases a couple of scripts handling all the requests (e.g. /index.php for front page and /wp-admin/index.php for the admin pages).

So you will have to correlate the time of the slow log request with the time in access.log in your web server.

To find the related access log requests, the easiest is having an aggregated log facility, e.g. PaperTrail.
In case of the aggregated log, you would simply scroll up through the log records above the slow PHP-FPM record to locate the one from the web server.

But you can simply use SSH for locating log entries. Simply browse the access log:

less access.log

Then type / followed by the time specifications of a minute when the PHP-FPM slow request took place, e.g. 12:16:, then hit Enter on your keyboard.

The text browser search for the specified text and you can easily locate the related access log entry.

For our sample request, the related entry in access.log is the following:

<IP> - - [05/Jun/2020:12:16:45 +0000] "GET /wp-admin/ HTTP/1.1" 200 46224 "-" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/79.0.3945.88 Safari/537.36" "<IP>, 127.0.0.1" "www.example.com" sn="www.example.com" rt=0.973 ua="unix:/var/run/php-fpm/php-fpm-example.com.sock" us="200" ut="0.973" ul="224549" cs=-

So simply browsing /wp-admin/ is slow. Why? Let’s look back at our slow PHP-FPM backtrace and see how to read it.

The function calls are listed in the order of recency: the function that ran earlier will be at the bottom; the function to run last will be at the top.
So we see that when the script exceeded the 3 seconds threshold, it was running curl_exec function, which indicates the most common reason of a slow website in modern content management systems – curl requests to remote websites.

The solution there is typically halting the often unnecessary requests from being made, or adjusting the URL of the requested remote services, if they are crucial to website’s function.

So how to identify which code is responsible for such requests, why and to which URLs? Simply read the slow entry from the bottom to the top.
The functions were in invoked in this order

• wp_dashboard_setup()
• wp_check_browser_version()
• wp_remote_post()
• …

You can browse through each function call via less as well.
While you can do it for each entry (in order to understand why the code ended up using curl_exec), you can use some intuition there. Run command:

less +1687 /srv/www/example.com/httpdocs/wp-admin/includes/dashboard.php

This will take you to where wp_remote_post was called. Navigating the code few lines above, you can locate the actual URL being invoked:

$url     = 'http://api.wordpress.org/core/browse-happy/1.1/';

A Google search away, is the answer to your query:

WordPress checks whether your browser is up-to-date, and displays a notice if it is not (i.e., “You are using an insecure browser!” or “Your browser is out of date!”).

Specific to this case, it is a WordPress behavior which calls its own API to check if your browser is up-to-date.
Thanks WordPress, if you do this, at least you should have used a faster web server for your API.

So you can disable this with a simple paste-in to your functions.php:

add_filter('pre_http_request', function($ret, array $request, string $url) {
    if (\preg_match('!^https?://api\.wordpress\.org/core/browse-happy/!i', $url)) {
        return new \WP_Error('http_request_failed', \sprintf('Request to %s is not allowed.', $url));
    }

    return $ret;
}, 10, 3);

Other common Causes of Slow Requests

Aside from slow curl function calls to remote services (a.k.a slow websites that makes your website slow), there are few other common cases why PHP is slow to run, and thus logged to slow PHP-FPM log

Slow MySQL queries

That will usually manifest in a form of logged mysql_query function calls. The issue is typically with a missing database index, which will speed up queries’ execution

Long running scripts running in web context

This is caused by long-running scripts launched via browser, where there shouldn’t be.
An example is a data import/export, that has to be executed via cron/message queues, etc.

Typical mistake is running website cron tasks via curl invocation in crontab. This is wrong in 99% cases.

E.g. curl http://example.com/cron.php simply makes no sense if cron.php is located on the same server as where you run curl. Simply rewrite cron to launch php interpreter directly, with argument set to the location of the cron file:

* * * * * /usr/bin/php /srv/www/example.com/cron.php

Tips

When you’re done fixing slow PHP requests, do not forget to disable PHP-FPM slow log on a production website by commenting directives that enabled it.

; slowlog = /srv/www/example.com/logs/slow.log
; request_slowlog_timeout = 3s

This ensures that PHP-FPM doesn’t incur additional overhead to keep the backtrace.