Redis get查询慢问题排查笔记

最近项目中有一个需求1s并发30左右就开始报redis get比较慢,php慢查询全是redis的get请求,但这样的并发不该出现这样的问题才对,于是开始写脚本检测redis的情况。


一、排查过程:

(1)监控redis的Info信息

(2)monitor记录redis接收和处理的命令,并使用Python脚本分析其结果。

(3)服务器IO实时监控和检查PHP的慢查询日志,redis get比较慢~

(4)分析以上信息发现redis有10几秒没有任何请求,判断应该是PHP-fpm或者redis出现问题

(5)分析PHP的错误日志,发现PHP-fpm一直被重启,查看当前php-fpm进程个数,320......,PHP错误如下:

[14-Aug-2018 23:03:07] WARNING: [pool www] child 126467, script '/datadrive/www_php/index.php' (request: "POST /index.php") executing too slow (3.953724 sec), logging
[14-Aug-2018 23:03:07] NOTICE: child 62402 stopped for tracing
[14-Aug-2018 23:03:07] NOTICE: about to trace 62402
[14-Aug-2018 23:03:07] ERROR: failed to ptrace(PEEKDATA) pid 62402: Input/output error (5)
[14-Aug-2018 23:03:07] NOTICE: finished trace of 62402
[14-Aug-2018 23:03:07] NOTICE: child 63255 stopped for tracing
[14-Aug-2018 23:03:07] NOTICE: about to trace 63255
[14-Aug-2018 23:03:07] ERROR: failed to ptrace(PEEKDATA) pid 63255: Input/output error (5)
[14-Aug-2018 23:03:07] NOTICE: finished trace of 63255
[14-Aug-2018 23:03:07] NOTICE: child 76942 stopped for tracing
[14-Aug-2018 23:03:07] NOTICE: about to trace 76942
[14-Aug-2018 23:03:07] ERROR: failed to ptrace(PEEKDATA) pid 76942: Input/output error (5)
[14-Aug-2018 23:03:07] NOTICE: finished trace of 76942
[14-Aug-2018 23:03:07] NOTICE: child 62348 stopped for tracing
[14-Aug-2018 23:03:07] NOTICE: about to trace 62348
[14-Aug-2018 23:03:07] ERROR: failed to ptrace(PEEKDATA) pid 62348: Input/output error (5)
[14-Aug-2018 23:03:07] NOTICE: finished trace of 62348


(6)分析PHP-fpm的配置文件,发现配置文件存在问题,系统内存6G,max_children、start_servers、min_spare_servers、max_spare_servers全部被设置为了320,每个PHP-fpm平均值大概在25兆左右,内存被占的满满地~~,查看这四个参数的具体含义:

php-fpm优化方法 pm.min_spare_servers、pm.max_spare_servers 的真实意义

(7)更改完PHP-fpm观察情况,发现还是会报警。。。

(8)编写Python脚本多线程调用url,开始实时监控硬盘IO情况,发现硬盘IO有一瞬间会飙升到20多兆。

(9)检查redis日志,错误如下:

98895:C 16 Aug 02:24:14.801 * DB saved on disk
98895:C 16 Aug 02:24:14.830 * RDB: 49 MB of memory used by copy-on-write
35525:M 16 Aug 02:24:14.889 * Background saving terminated with success
35525:M 16 Aug 02:29:15.041 * 10 changes in 300 seconds. Saving...
35525:M 16 Aug 02:29:15.076 * Background saving started by pid 100759
35525:M 16 Aug 02:29:34.088 * Asynchronous AOF fsync is taking too long (disk is busy?). Writing the AOF buffer without waiting for fsync to complete, this may slow down Redis.

(10)检查redis配置文件,发现Redis的持久化方式rdb和aof全开了,关闭rdb方式再次并发测试,Ok.问题解决。

修改内容:将redis的save设置为空,redis-cli中使用

config set save ""

以上设置重启redis将失效,需修改配置文件:


二、排查过程中编写的脚本

(1)监控redis的Info信息

(2)利用redis的monitor监控处理的命令

(3)Python多线程GET和POST读取URL内容

三、相关命令

##########redis###############
INFO commandstats #重置统计信息
CONFIG RESETSTAT  #重置统计信息
info #查看redis相关信息
redis-cli --latency -h 127.0.0.1 -p 6379 #查看延迟情况
slowlog get #查看慢命令记录
############PHP###############
echo '<?php phpinfo(); ?>' | php 2>&1 |grep -i error_log #查看错误日志存放位置


by 雪洁 2018-08-15 05:45:45 482 views
我来说几句

相关文章