Wednesday, November 20, 2013

Debugging PHP Scripts Using slow_log and more



If you are an old PHP programmer, you must have used PHP’s error_log function sometime. But PHP itself does not provide a way to find out slowly executing scripts. Slow scripts are not the ones which break your site but they slow-down everything. Using FPM, we can have a slow_log for all such scripts. Let’s see how to use these logs to debug PHP scripts. Also, we will see how PHP’s error_log gets diverted if it is running behind FPM and Nginx.

Setup slow_log for PHP scripts

Open… vim /etc/php5/fpm/pool.d/www.confMake necessary changes to match 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 which execute slowly. Image resizing function, network I/O related functions are some examples which will frequently show-up in PHP slow_log. Its up to you to debug them or ignore them based on your context.

Setup error_log for PHP scripts

When running PHP using FPM, we can override any php.ini setting from FPM. Open… vim /etc/php5/fpm/pool.d/www.confScroll down towards bottom and uncomment/change following 3 lines to match values given below:
php_admin_value[error_log] = /var/log/php5/error.log
php_admin_flag[log_errors] = on
Please note that turning on display_errors can break ajax-based applications. So be really careful with this.

Important for Nginx Users

You will not see a file/var/log/php5/error.log or not any error being logged in that file. Errors in your PHP scripts for a site will go intoerror_log specified for that site in its nginx config. Most likely: /var/www/example.com/logs/error.log file If you haven’t specified any 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 details here about debugging with Nginx.

Setup FPM error_log to debug FPM itself

FPM is separate process. Like others, it can run into errors itself! FPM’s error_log is on by default but we will change its path to meet our convention. Open… vim /etc/php5/fpm/php-fpm.conf Make sureerror_log value looks like below
error_log = /var/log/php5/fpm.log
Please note that this error_log is not related to PHP’s error_log function described before.

Confirm Changes…

Create php5 log directory so we can have all PHP logs in one place:
mkdir /var/log/php5/
Restart PHP-FPM for changes to take effect…
service php5-fpm restart

Monitoring log file

Best way to open a separate shell on your server and use tail -f command to monitor logs… As we have multiple log files to monitor, you can simply use following command to monitor all of them together…
tail -f /var/log/php5/*.log
slow_log helped us many times to eliminate bottlenecking from our applications.
Always remember to turn it off when you are done with debugging. Leaving slow_log on is not a good idea.