The slow query on the master caused the redis replication lag

Redis复制延迟问题在线上已经碰到过多次,多个同事找我也问起这个问题。事出异常必有妖,必然有蛛丝马迹可以寻找到真相。用最近的线上的一个redis产生replication lag问题,详细介绍下如何分析该类问题。

1 Redis Replication Lag
replication lag的监控来自master redis info中的slave信息,比如,

slave0:ip=192.168.54.172,port=6379,state=online,offset=28608871499592,lag=5

lag表示master节点和slave节点之间复制心跳丢失的时间,即master多长时间已经没有收到从库replconf ack请求。

2 Redis Master-Slave Hearbet (1 seconds)

redis slave节点每个一秒向master节点发送replconf ack确认复制的状态,lag是master节点上次接受到slave节点发出replconf ack命令到当前的时间间隔。当lag>1时,必然有replconf ack命令处理延迟,可能是master原因,也有可能是slave的原因。

这次发现有问题的redis是因为redis中的慢查询导致的复制延迟,大量的慢查询(slow query time >1 seconds)。


3 Find the Root Cause

在slave节点上,日志显示和主库的链接异常,请求SYNC操作,master回复可以增量复制,slave请求PSYNC。

233939:S 05 Apr 15:52:18.075 * MASTER <-> SLAVE sync started
233939:S 05 Apr 15:52:18.075 * Non blocking connect for SYNC fired the event.
233939:S 05 Apr 15:52:31.242 # Error condition on socket for SYNC: Connection reset by peer
233939:S 05 Apr 15:52:32.098 * Connecting tothe MASTER 192.168.80.159:7001
233939:S 05 Apr 15:52:32.098 * MASTER <-> SLAVE sync started
233939:S 05 Apr 15:52:35.099 * Non blocking connect for SYNC fired the event.
233939:S 05 Apr 15:52:35.099 * Master replied to PING, replication can continue...
233939:S 05 Apr 15:52:35.099 * Trying a partial resynchronization (request 0369001a8f6e26ee4d12cef4e8cf98c175bffea1:53504534071).
233939:S 05 Apr 15:52:35.131 * Successful partial resynchronization with master.
233939:S 05 Apr 15:52:35.131 * MASTER <-> SLAVE sync: Master accepted a Partial Resynchronization.

master节点日志显示也是复制相关的信息。

193475:M 05 Apr 15:52:35.101 * Slave 192.168.130.28:7001 asks for synchronization
193475:M 05 Apr 15:52:35.116 * Partial resynchronization request from 192.168.130.28:7001 accepted. Sending 5155 bytes of backlog starting from offset 53504534071.

首先可以排除网络的原因,只能从redis内部性能分析,找到了元凶。毫无疑问,如果redis性能问题,必然有大量的慢查询产生

从redis slow log中也确实找到了大量慢查询记录,如下。
3) 1) (integer) 149594
2) (integer) 1491378610
3) (integer) 1502602
4) 1) “lrange”
2) “api.com_commonds”
3) “0”
4) “-1″

其中“ 3) (integer) 1502602”表示命令的执行时间,“lrange mapi.vip.vip.com_commonds 0 -1″执行在一个大的集合上</font”>,花费了1.5s时间。



4 Summary

redis是单进程工作模式,不管是OS的性能问题(swap,high load)还是客户端的慢查询导致的长产时间阻塞,会使一些周期性的时间时间调度收到影响,致使redis产生异常的行为。


此条目发表在redis分类目录,贴了, , 标签。将固定链接加入收藏夹。

发表评论

电子邮件地址不会被公开。 必填项已用*标注

您可以使用这些HTML标签和属性: <a href="" title=""> <abbr title=""> <acronym title=""> <b> <blockquote cite=""> <cite> <code> <del datetime=""> <em> <i> <q cite=""> <strike> <strong>