PHP-FPM slow log - what is this and how is it used

[isscbta]

PHP-FPM has a slow log, this can be used to find which PHP line (in what PHP scripts) caused the PHP process to be held for so long.

For this particular example, we used it to see where the PHP process got stuck at the exact moment 10 seconds after the script was executed (because we know it will run for at least 15 seconds long).
As well, we can use this to diagnose the reason for being stuck.

The php-fpm slow log is a pool configuration, meaning that we configure it in pool.d conf file, and has two directives for it:

• the slowlog, which is a path to a log file where the slow requests will be logged,
• and request_slowlog_timeout is a time unit after which PHP will dump a backtrace for that request in to the slow log file.

To enable this, we need to edit /etc/php/x.x/fpm/pool.d/example.com.conf file.

First, check what PHP version you are running on the example.com domain.

In your SSH run:

Code: Select all

sudo /usr/local/vesta/bin/v-get-php-version-of-domain example.com

The output will be, for example:

Code: Select all

8.0

Now we know the location of our PHP-FPM pool.d conf, it's: /etc/php/8.0/fpm/pool.d/example.com.conf

Let's edit your PHP-FPM pool.d conf:

Code: Select all

sudo mcedit /etc/php/8.0/fpm/pool.d/example.com.conf

Add this into that file:

Code: Select all

slowlog=/home/USER/slow.log
request_slowlog_timeout=10s

(instead 'USER' put your myVesta username)


Press F2 on your keyboard and confirm saving.

Press ESC twice on your keyboard to exit the editor.

At the end, restart PHP-FPM:

Code: Select all

sudo systemctl restart phpX.X-fpm

(where X.X is PHP version of your domain)
For example:

Code: Select all

sudo systemctl restart php8.0-fpm

Wait a few moments or access the site via browser - when the first PHP request reaches the 10th second of execution, we will have something in the log.

So, let's take a look at the log file:

Code: Select all

tail -f /home/USER/slow.log

And here is the output:

script_filename = //home/user/web/example.com/public_html/index.php
[0x00007f72afe13730] curl_exec() /home/user/web/example.com/public_html/style-editor.php:19
[0x00007f72afe135d0] [INCLUDE_OR_EVAL]() /home/user/web/example.com/public_html/wp-content/themes/user/footer.php:191
[0x00007f72afe13570] [INCLUDE_OR_EVAL]() /home/user/web/example.com/public_html/wp-includes/template.php:770
[0x00007f72afe13410] load_template() /home/user/web/example.com/public_html/wp-includes/template.php:716
[0x00007f72afe13320] locate_template() /home/user/web/example.com/public_html/wp-includes/general-template.php:92
[0x00007f72afe13270] get_footer() /home/user/web/example.com/public_html/wp-content/themes/user/single.php:174
[0x00007f72afe131c0] [INCLUDE_OR_EVAL]() /home/user/web/example.com/public_html/wp-includes/template-loader.php:106
[0x00007f72afe13100] [INCLUDE_OR_EVAL]() /home/user/web/example.com/public_html/wp-blog-header.php:19
[0x00007f72afe13070] [INCLUDE_OR_EVAL]() /home/user/web/example.com/public_html/index.php:17

The line script_filename= is the PHP filename that got an HTTP request, and that is often index.php.
The first line after script_filename= is what we are looking for.

Code: Select all

[0x00007f72afe13730] curl_exec() /home/user/web/example.com/public_html/style-editor.php:19

In this example, this means that after 10 seconds of executions, PHP was executing /home/user/web/example.com/public_html/style-editor.php script on line 19, waiting for curl_exec() for the return value.
The curl_exec() command waited for a response from some other (remote) site, the remote server/site was probably offline or busy, and that caused our PHP script to run for more than 10 seconds.

Everything below this line is a backtrace (the steps that preceded this code).