相信很多人都知道,mysql有slow query log,根据慢查询日志,我们可以知道那些sql语句有性能问题。作为mysql的好搭档,php也有这样的功能。
一、开启slow log方法:
如果你使用php-fpm来管理php的话,你可以通过如下方法开启:
首先打开 php-fpm.conf 配置文件。
- vim /usr/local/php/etc/php-fpm.conf
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/var/log/php-fpm-slowlog.log
- request_terminate_timeout = 10s
说明:
request_slowlog_timeout 是脚本超过多长时间,就可以记录到日志文件;
slowlog 是日志文件的存储路径;
request_terminate_timeout 将执行时间太长的进程直接终止;
二、slow log如何使用?
开启后,如果有脚本执行超过指定的时间,就会在指定的日志文件中写入类似如下的信息:
- [06-Dec-2017 20:05:31] [pool www] pid 22271
- script_filename = /home/wwwroot/default/tz/tz.php
- [0x00007f75e662a398] preg_match_all() /home/wwwroot/default/tz/tz.php:453
- [0x00007f75e6627f08] sys_linux() /home/wwwroot/default/tz/tz.php:410
由于我把slow log日志放在 /usr/local/php/var/log/php-fpm-slowlog.log 这里,只需要查看此日志即可!
- vim /usr/local/php/var/log/php-fpm-slowlog.log
除了用vim,用cat、tail、head等都可以。
三、slow log 分析
下面是我截的一张日志图片,来做一个简单的分析吧!
说明:
script_filename 是入口文件;
session_start、session、run、start、sleep : 说明是执行这个方法的时候超过执行时间的。
每行冒号后面的数字是行号。
开启后,在错误日志文件(php-fpm.log)中也有相关记录。如下:
- [06-Dec-2017 20:59:53] NOTICE: finished trace of 31450
- [06-Dec-2017 20:59:56] WARNING: [pool www] child 31437, script '/home/wwwroot/default/tz/tz.php' (request: "GET /tz/tz.php") executing too slow (1.047562 sec), logging
- [06-Dec-2017 20:59:56] NOTICE: child 31437 stopped for tracing
- [06-Dec-2017 20:59:56] NOTICE: about to trace 31437
- [06-Dec-2017 20:59:56] NOTICE: finished trace of 31437
- [06-Dec-2017 21:00:05] WARNING: [pool www] child 31448, script '/home/wwwroot/default/tz/tz.php' (request: "GET /tz/tz.php") executing too slow (1.013736 sec), logging
- [06-Dec-2017 21:00:05] NOTICE: child 31448 stopped for tracing
- [06-Dec-2017 21:00:05] NOTICE: about to trace 31448
- [06-Dec-2017 21:00:05] NOTICE: finished trace of 31448
- [06-Dec-2017 21:00:10] WARNING: [pool www] child 31481, script '/home/wwwroot/default/TTTTT_GAME/index.php' (request: "GET /TTTTT_GAME/index.php") executing too slow (1.134845 sec), logging
- [06-Dec-2017 21:00:10] WARNING: [pool www] child 31478, script '/home/wwwroot/default/TTTTT_GAME/index.php' (request: "GET /TTTTT_GAME/index.php") executing too slow (1.169301 sec), logging
- [06-Dec-2017 21:00:10] WARNING: [pool www] child 31475, script '/home/wwwroot/default/TTTTT_GAME/index.php' (request: "GET /TTTTT_GAME/index.php") executing too slow (1.009847 sec), logging
- [06-Dec-2017 21:00:10] WARNING: [pool www] child 31468, script '/home/wwwroot/default/TTTTT_GAME/index.php' (request: "GET /TTTTT_GAME/index.php") executing too slow (1.019848 sec), logging
- [06-Dec-2017 21:00:10] WARNING: [pool www] child 31455, script '/home/wwwroot/default/TTTTT_GAME/index.php' (request: "GET /TTTTT_GAME/index.php") executing too slow (1.147848 sec), logging
- [06-Dec-2017 21:00:10] WARNING: [pool www] child 31451, script '/home/wwwroot/default/TTTTT_GAME/index.php' (request: "GET /TTTTT_GAME/index.php") executing too slow (1.076841 sec), logging
- [06-Dec-2017 21:00:10] WARNING: [pool www] child 31447, script '/home/wwwroot/default/TTTTT_GAME/index.php' (request: "GET /TTTTT_GAME/index.php") executing too slow (1.119846 sec), logging
- [06-Dec-2017 21:00:10] WARNING: [pool www] child 31443, script '/home/wwwroot/default/TTTTT_GAME/index.php' (request: "GET /TTTTT_GAME/index.php") executing too slow (1.177849 sec), logging
- [06-Dec-2017 21:00:10] WARNING: [pool www] child 31436, script '/home/wwwroot/default/TTTTT_GAME/index.php' (request: "GET /TTTTT_GAME/index.php") executing too slow (1.092818 sec), logging
- [06-Dec-2017 21:00:10] WARNING: [pool www] child 31433, script '/home/wwwroot/default/TTTTT_GAME/index.php' (request: "GET /TTTTT_GAME/index.php") executing too slow (1.162842 sec), logging
- [06-Dec-2017 21:00:10] NOTICE: child 31433 stopped for tracing
- [06-Dec-2017 21:00:10] NOTICE: about to trace 31433
- [06-Dec-2017 21:00:10] ERROR: failed to ptrace(PEEKDATA) pid 31433: Input/output error (5)
- [06-Dec-2017 21:00:10] NOTICE: finished trace of 31433
- [06-Dec-2017 21:00:10] NOTICE: child 31436 stopped for tracing
- [06-Dec-2017 21:00:10] NOTICE: about to trace 31436