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

Post Reply
User avatar
isscbta
Posts: 61
Joined: Mon Jul 19, 2021 1:41 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:
  • 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, edit /etc/php/7.x/fpm/pool.d/your-domain.com.conf and add this:

Code: Select all

slowlog=/home/USER/slow.log
request_slowlog_timeout=10s
Now restart PHP-FPM:

Code: Select all

systemctl restart php7.x-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/domain.com/public_html/index.php
[0x00007f72afe13730] curl_exec() /home/user/web/domain.com/public_html/style-editor.php:19
[0x00007f72afe135d0] [INCLUDE_OR_EVAL]() /home/user/web/domain.com/public_html/wp-content/themes/user/footer.php:191
[0x00007f72afe13570] [INCLUDE_OR_EVAL]() /home/user/web/domain.com/public_html/wp-includes/template.php:770
[0x00007f72afe13410] load_template() /home/user/web/domain.com/public_html/wp-includes/template.php:716
[0x00007f72afe13320] locate_template() /home/user/web/domain.com/public_html/wp-includes/general-template.php:92
[0x00007f72afe13270] get_footer() /home/user/web/domain.com/public_html/wp-content/themes/user/single.php:174
[0x00007f72afe131c0] [INCLUDE_OR_EVAL]() /home/user/web/domain.com/public_html/wp-includes/template-loader.php:106
[0x00007f72afe13100] [INCLUDE_OR_EVAL]() /home/user/web/domain.com/public_html/wp-blog-header.php:19
[0x00007f72afe13070] [INCLUDE_OR_EVAL]() /home/user/web/domain.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/domain.com/public_html/style-editor.php:19
In this example, this means that after 10 seconds of executions, PHP was executing /home/user/web/domain.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).

Tags:
Post Reply