上个星期,在线上发现一个redis在只有200不到的qps时,进程cpu使用(top观测值)率达到了40%+。对于这个问题分析了好久,包括慢查询和响应时间的分析都无异常。决定对这个线上的redis进程做了一把strace操作,后果是前端应用在短时间内出现了5w+的5xx错误。strace操作导致了进程的阻塞引起了,虽然引起了一个故障,但是strace日志还是对问题的分析还是有很大的帮助。
1、大致的分析过程
# strace -T -tt -f -p 92028 -o 92028.txt
通过日志发现,redis有大量的socket操作,特别是大量的accept、close、setsocketopt的系统调用。而实际的数据读写操作write很少(redis向外写数据),也就是客户端实际的请求很少。
# awk '{print $3}' 92028.txt | awk -F '(' '{print $1}' |sort uniq -c 19862 accept 18132 close 38322 epoll_ctl 20 epoll_wait 39723 fcntl 2 futex 19 open 18306 read 19861 setsockopt 168 write
再统计请求来源,也证实了这一点,每台前端应用服务器平均每秒会创建25个连接。
# grep accept 92028.txt|grep 16:58:15 |grep -Po '192\.168\.\d{2,}\.\d{2,}'|sort|uniq -c 29 193.168.81.106 23 193.168.83.100 24 193.168.83.101 27 193.168.83.102
2、redis info中关于连接数的监控
– connected_clients: Number of client connections (excluding connections from slaves)
– total_connections_received: Total number of connections accepted by the server
connected_clients,可以认为是某一瞬间的看到的连接数,具体的连接来源可以通过client list命令查看。
total_connections_received,接收到的链接数据,是累加值,可以算出一段时间内存redis的接受到的请求数,比如每分秒的连接数CPS。
3、问题重现
重现问题,大量的短连接导致消耗redis消耗大量的cpu资源。模拟过程如下,在多个客户端发起连接,并只执行quit命令,创造大量的短连接。
for((;;));do redis-cli -h 192.168.61.30 -p 6379 quit ;done
总结:
有时候对监控metric的错误理解会导致排查问题走入错误的方向,比如我一直认为connected_clients是CPS。
参考文献:
https://redis.io/commands/INFO