PHP-FPM slow log - what is this and how is it used
Posted: Mon Nov 14, 2022 10:17 am
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:
First, check what PHP version you are running on the example.com domain.
In your SSH run:
The output will be, for example:
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:
Add this into that file:
(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:
(where X.X is PHP version of your domain)
For example:
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:
And here is the output:
The first line after script_filename= is what we are looking for.
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).
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.
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
Code: Select all
8.0
Let's edit your PHP-FPM pool.d conf:
Code: Select all
sudo mcedit /etc/php/8.0/fpm/pool.d/example.com.conf
Code: Select all
slowlog=/home/USER/slow.log
request_slowlog_timeout=10s
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
For example:
Code: Select all
sudo systemctl restart php8.0-fpm
So, let's take a look at the log file:
Code: Select all
tail -f /home/USER/slow.log
The line script_filename= is the PHP filename that got an HTTP request, and that is often index.php.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 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
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).