Debugging PHP scripts using slow_log and more

php Analysis of slow script execution If you are an old PHP programmer, you should have used the PHP error_log function for a while . But by itself, PHP does not provide a way to figure out slow script execution. Slow scripts are not the ones that break your site, but they slow everything down. Using FPM, we can have slow_log for all such scenarios. Let's see how to use these logs to debug PHP scripts. In addition , we will see how in PHP error_log gets redirected if it works for FPM and Nginx.

Setting slow_log for PHP scripts

View ... ВИМ /etc/php5/fpm/pool.d/www.conf Make the necessary changes to match the following values:

  slowlog = /var/log/php5/slow.log 
  request_slowlog_timeout = 10s

You can replace 10s with any other value. This will help us find scripts that run slowly. image resizing function, I / O network corresponding functions are some examples that will often show up in PHP slow_log. Its up to you to debug them or ignore them based on your context.

Setting error_log for PHP scripts

When running PHP using FPM, we can override any php.ini settings from FPM. Open ... ВИМ /etc/php5/fpm/pool.d/www.conf Scroll down to the bottom and uncomment / change the following 3 lines to match the values below:

  php_admin_value [error_log] = /var/log/php5/error.log 
  php_admin_flag [log_errors] = on

Please note that turning on display_errors may break Ajax applications. So be very careful with this.

Important for nginx users

You will not see the /var/log/php5/error.log file or if any error is logged in this file. Errors in your scripts for the site will go to the error_log specified for this site in its Nginx configuration. Most likely: /var/www/example.com/logs/error.log файл If you did not specify the error_log path for your site, then PHP errors will go to Nginx’s default error_log. Most likely ( /var/log/nginx/error.log file) You can find more detailed information here on debugging with Nginx .

Configure FPM error_log to debug FPM itself

FPM is a separate process. Like others, it may work in self errors! Error_log FPM is the default, but we will change our path to satisfy our agreement. View ... ВИМ /etc/php5/fpm/php-fpm.conf Make sure the error_log value looks as shown below

  error_log = /var/log/php5/fpm.log

Please note that this error_log is not related to the PHP in the error_log function described earlier.

Confirm changes ...

Creating a php5 log directory so we can have all the php logs in one place:

  MkDir / Var / Journal / php5 /

Rebooting PHP-FPM for the changes to take effect ...

  service php5-fpm restart

Monitoring log file

The best way to open a separate shell on your server and use the хвост -f command to monitor logs ... As we have several log files to monitor, you can simply use the following command to monitor them all together ...

  Tail -f /var/log/php5/*.log

slow_log helped us many times to exclude from our narrow applications.

Always remember to turn it off when you're done with debugging. Leaving slow_log on is not a good idea.

Analyzing php-fpm.slow.log

So, that day came when you or your colleague, finally, launched a serious project, be it a portal / social network / game for social networks. But, as always, suddenly, the project begins to slow down. What's the matter? After all, the base is configured as it should, and the cache is used, even nginx with a PHP code accelerator is working hard.

In order not to cover all the code with some benchmark, you can use the great php-fpm logging feature to dump scripts that have been running for more than N seconds to identify bottlenecks. This miracle is enabled in php-fpm.conf.

What to do?

First of all, you should find and fix the code in those places where the problem occurs most often. The following example will help us in this.

//чтобы отсечь лишнее, подбирается под конкретные задачи анализа лога, список функций легко определить на глаз при открытии файла лога 
 $functions=array( 
 "mysql_query", 
 "session_start", 
 ); 
 
 //функция очищения пути к файлу 
 function clear_path($path) 
 { 
 return str_replace("/home/","",$path); 
 } 
 
 //открываем и парсим лог 
 $f=fopen("/path/to/php-fpm.log.slow.1","r"); 
 if ($f) 
 while (($row=fgets($f,4096))!==false) 
 { 
 foreach ($functions as $function) 
 if (strpos($row,$function)!==false) 
 { 
 $path=explode(" ",$row); 
 $path=array_pop($path); 
 $path=explode(":",$path); 
 $result[clear_path($path[0])][trim($path[1])]++; 
 } 
 } 
 print_r($result);

At the output we get an array, the keys of which are the path to the problem file, and the values are the second array, the keys of which are the string in the file, the value is the number of executions for more than N seconds.

Array 
 ( 
 [/path/to/script1.php] => Array 
 ( 
 [7] => 9 
 ) 
 
 [/path/to/script2.php] => Array 
 ( 
 [64] => 5 
 ) 
 
 [/path/to/script3.php] => Array 
 ( 
 [375] => 1 
 [468] => 39 
 [358] => 1 
 [391] => 5 
 [249] => 1 
 [154] => 2 
 ) 
 )

Then everyone can set up the output in a form more pleasing to the eye.

What else should you know

In the new format php-fpm.slow.log there is also the ability to view the parameters passed to the script, the execution time itself is shown.
script_filename = /data/www/forum.php mod=rss&fid=3378&auth=0 (0.550162 sec)
Having made a simple modification of the example, namely, by adding the line processing with the script_filename, you can get a little more information for debugging.

Conclusion

After solving the problems revealed by this analysis, most likely, your server will again delight its visitors with flawless work, and you will only have to glance occasionally in slow.log for your own peace of mind.

php Analysis of slow script execution