PHP慢日志slow_log

发表于

    php-fpm慢日志slowl_og设置可以让开发者很好的查找哪些php进程速度过慢而导致的网站问题，让开发者方便的找到问题的所在。该方法同样适用于排查nginx的500、502问题根源，当nginx收到如上错误码时，可以确定后端php-fpm解析php出了某种问题，比如，执行错误，执行超时等。

参数设置

php-fpm.conf的配置文件中有一个参数request_slowlog_timeout是这样描述的：

; 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 = 0

1
2
1. 当request_slowlog_timeout设为一个具体秒时,比如request_slowlog_timeout =5，表示如果哪个脚本执行时间大于5秒，会记录这个脚本到慢日志文件中。
2. request_slowlog_timeout =0表示关闭慢日志输出

日志位置设置

慢日志文件位置默认在php的安装目录下的log文件夹中，可以通过修改slowlog = log/$pool.log.slow参数来指定,如下，慢日志会记录下进程号，脚本名称，具体哪个文件哪行代码的哪个函数执行时间过长：

1
2
3
4
[21-Nov-2013 14:30:38] [pool www] pid 11877
script_filename = /usr/local/nginx/html/www.quancha.cn/www/fyzb.php
[0xb70fb88c] file_get_contents() /usr/local/nginx/html/www.quancha.cn/www/fyzb.php:2
[21-Nov-2013 14:15:23] ERROR: [pool www] 'slowlog' must be specified for use with 'request_slowlog_timeout'
  1. request_slowlog_timeout 和 slowlog 需要同时设置
  2. 需要手动创建slowlog文件夹

日志说明

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

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

日志说明：

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

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

1
2
3
4
[19-Dec-2013 15:55:37] WARNING: [pool www] child 18575, script '/home/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

使用举例

问题一描述：

在一次nginx应用更新的灰度过程中，我们选取一台nginx上线，观察接下来的半小时内，nginx占用内存不断增大，直到耗尽系统资源。

问题一排查步骤：

  1. 排查error_log中并没有错误信息；
  2. 监控发现新上线的nginx流量大增；
  3. 分析access_log发现新上线的nginx的QPS是原机器的6~8倍。
  4. 证实是Keepalived导致流量负载不均衡。LVS作为负载均衡时，后端的nignx配置的keepalive_timeout时间有差异导致。

LVS的负载均衡是TCP层的，只能做连接的均衡，如果Keepalive时间设置的超长，会导致路由到这个连接的请求越多

问题二描述：

nginx做反向代理，有时发现某些接口较慢，通常都在3s左右。

问题二排查步骤：

  1. 配置nginx的access log记录upstream_response_time
  2. 分析发现响应大约3s多。
  3. 分析后端的access_log，处理时间都在毫秒级别。这说明问题是由于nginx跟后端connect较慢导致

参考博客：

  1. http://blog.csdn.net/leonpengweicn/article/details/42494813
  2. 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/