善用php-fpm的慢执行日志slow log，分析php性能问题

来源：http://www.bo56.com/%E5%96%84%E7%94%A8php-fpm%E7%9A%84%E6%85%A2%E6%89%A7%E8%A1%8C%E6%97%A5%E5%BF%97slow-log%EF%BC%8C%E5%88%86%E6%9E%90php%E6%80%A7%E8%83%BD%E9%97%AE%E9%A2%98/

众所周知，mysql有slow query log，根据慢查询日志，我们可以知道那些sql语句有性能问题。作为mysql的好搭档，php也有这样的功能。如果你使用php-fpm来管理php的话，你可以通过如下选项开启。
PHP 5.3.3 之前设置如下：
<value name=”request_slowlog_timeout”>5s</value>
<value name=”slowlog”>logs/php-fpm-slowlog.log</value>

PHP 5.3.3 之后设置以下如下：
request_slowlog_timeout = 5s
slowlog = /usr/local/php/log/php-fpm-slowlog.log

说明：
request_slowlog_timeout 是脚本超过多长时间 就可以记录到日志文件
slowlog 是日志文件的路径

开启后，如果有脚本执行超过指定的时间，就会在指定的日志文件中写入类似如下的信息：

[19-Dec-2013 16:54:49] [pool www] pid 18575
script_filename = /home/admin/web/htdocs/sandbox_canglong/test/tt.php
[0x0000000003a00dc8] curl_exec() /home/admin/web/htdocs/sandbox_canglong/test/tt.php:2
[0x0000000003a00cd0] exfilter_curl_get() /home/admin/web/htdocs/sandbox_canglong/test/tt.php:6

日志说明：
script_filename 是入口文件
curl_exec() ： 说明是执行这个方法的时候超过执行时间的。
exfilter_curl_get() ：说明调用curl_exec()的方法是exfilter_curl_get() 。
每行冒号后面的数字是行号。

开启后，在错误日志文件中也有相关记录。如下：

[19-Dec-2013 15:55:37] WARNING: [pool www] child 18575, script ‘/home/admin/web/htdocs/sandbox_canglong/test/tt.php’ (request: “GET /test/tt.php”) executing too slow (1.006222 sec), logging
[19-Dec-2013 15:55:37] NOTICE: child 18575 stopped for tracing
[19-Dec-2013 15:55:37] NOTICE: about to trace 18575
[19-Dec-2013 15:55:37] NOTICE: finished trace of 18575

php的错误日志与慢日志配置

一 错误输出

找到php.ini

log_errors = On

; Log errors to specified file.
error_log = /Data/logs/php/error.log

比如会捕获到类似信息：

[23-Oct-2011 17:17:41] PHP Fatal error:  Class 'Strclass' not found in /Data/webapps/www.aslibra.com/application/errors/error_404.php on line 11

这个有助于分析被访问的页面发生的致命错误或者是警告

二 慢日志

慢日志和数据库的慢查询有点类似，会记录下来执行超过多少时间的php执行的内容
这个如果是用fast-cgi的话，可以在fpm的配置里面有

      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">10s</value>

      The log file for slow requests
      <value name="slowlog">/Data/logs/php/slow.log</value>

比如上面是记录超过10秒的php，记录在相应的文件里
你可以拿到类似的日志：

Oct 23 23:00:20.528849 pid 11586 (pool default)
script_filename = /www.aslibra.com/index.php
[0x00007fffae1869e0] mysql_query() /www.aslibra.com/system/database/drivers/mysql/mysql_driver.php:163
[0x00007fffae186bb0] _execute() /www.aslibra.com/system/database/DB_driver.php:453
[0x00007fffae186eb0] simple_query() /www.aslibra.com/system/database/DB_driver.php:299
[0x00007fffae1870b0] query() /www.aslibra.com/v3/models/myuser.php:51
[0x00007fffae1872a0] get_users_by_uids() /www.aslibra.com/v3/models/myuser.php:58
[0x00007fffae187580] get_users() /www.aslibra.com/v3/controllers/pic.php:134
[0x00007fffae187870] experience() /www.aslibra.com/v3/controllers/pic.php:349
[0x00007fffae187940] user() unknown:0
[0x00007fffae187cf0] call_user_func_array() /www.aslibra.com/system/core/CodeIgniter.php:297
[0x00007fffae187f40] +++ dump failed

日志里包含的信息：执行时间，访问入口，执行的函数的顺序和所有父级调用关系
比如这里可以获知是数据库查询时出现过慢，调用关系也一目了然，可以去排查跟踪了