善用 PHP-FPM 的 slow log 分析問題

做者：Hily 原始連接：http://hily.me/blog/2011/02/use-php-fpm-slow-log-to-investigate-problem/
版權聲明：能夠轉載，轉載時務必以超連接形式標明文章原始出處和做者信息及版權聲明

節前公司站點出現了莫名的 502 錯誤，在服務器配置上拆騰未果，從新開始懷疑程序問題。

關於 502 錯誤，具體能夠參考如下兩篇文章：
《自動檢測 PHP-FPM 的錯誤並重啓的 PHP 腳本》
《NGINX + PHP-FPM 502 相關事》

根據錯誤提示(11: Resource temporarily unavailable) ，排除掉服務器配置的問題，天然而然就懷疑是資源被程序佔用光了。

這些資源包括數據庫鏈接、文件數、鎖等等，若是一個個去猜解調試甚至是走讀代碼，未免太費時間，也未必能發現問題所在。

好在 PHP-FPM 提供了慢執行日誌，能夠將執行比較慢的腳本的調用過程 dump 到日誌中。

配置比較簡單，PHP 5.3.3 以前設置以下：

  The timeout (in seconds) for serving of single request after which a php backtrace will be dumped to slow.log file '0s' means 'off' <value name="request_slowlog_timeout">1s</value>  The log file for slow requests <value name="slowlog">logs/slow.logs</value> 

PHP 5.3.3 以後設置如下以下：

  ; The timeout for serving a single request after which a PHP backtrace will be ; dumped to the 'slowlog' file. A value of '0s' means 'off'. ; Available units: s(econds)(default), m(inutes), h(ours), or d(ays) ; Default Value: 0 request_slowlog_timeout = 1s  ; The log file for slow requests ; Default Value: /usr/local/php/log/php-fpm.log.slow slowlog = /usr/local/php/log/php-fpm.log.slow 

還能夠將執行時間太長的進程直接終止，設置下執行超時時間便可。
PHP 5.3.3 以前版本：

  The timeout (in seconds) for serving a single request after which the worker process will be terminated Should be used when 'max_execution_time' ini option does not stop script execution for some reason '0s' means 'off' <value name="request_terminate_timeout">10s</value> 

PHP 5.3.3+：

  ; The timeout for serving a single request after which the worker process will ; be killed. This option should be used when the 'max_execution_time' ini option ; does not stop script execution for some reason. A value of '0' means 'off'. ; Available units: s(econds)(default), m(inutes), h(ours), or d(ays) ; Default Value: 0 request_terminate_timeout = 10s 

加上慢執行日誌後，咱們能夠很容易從慢執行日誌中看出問題所在，好比：

  Feb 07 19:00:30.378095 pid 27012 (pool default) script_filename = /www/adshow/a.php [0x000000000115ea08] flock() /www/backend/parser/logs.class.php:260 [0x0000000001159810] lock_stats() /www/adshow/a.php:126  Feb 07 19:00:31.033073 pid 27043 (pool default) script_filename = /www/adshow/a.php [0x00000000012686e8] flock() /www/backend/parser/logs.class.php:260 [0x00000000012634f0] lock_stats() /www/adshow/a.php:126  Feb 07 19:00:31.163995 pid 26979 (pool default) script_filename = /www/adshow/a.php [0x000000000115bda8] flock() /www/backend/parser/logs.class.php:260 [0x0000000001156bb0] lock_stats() /www/adshow/a.php:126  Feb 07 19:00:31.164102 pid 27033 (pool default) script_filename = /www/adshow/a.php [0x00000000013f3fa8] flock() /www/backend/parser/logs.class.php:260 [0x00000000013eedb0] lock_stats() /www/adshow/a.php:126  Feb 07 19:00:31.297313 pid 27448 (pool default) script_filename = /www/adshow/a.php [0x0000000001180218] flock() /www/backend/parser/logs.class.php:260 [0x000000000117b020] lock_stats() /www/adshow/a.php:126 

很明顯是程序中產生了死鎖，致使各個 PHP-CGI 進程互相等待資源而鎖死。
據此，再進行進一步的程序分析，就更具方向性了。

– EOF –