在一个阳光明媚的下午,突然生产环境有一个缓存实例发出内存使用率超过90%的告警,然后立刻和小伙伴们一起看是什么情况。
现象是这样的,集群里的一个实例的内存使用率超过了90%,而这个实例的从节点,内存使用率却很低。而且其他分片的内存使用率都很低,只有这个分片高。见下图cachecloud实例状态图。
首先想到的肯定是大key导致的集群倾斜了,于是就先把这个分片的数据dump出来,然后使用rdbtools工具分析下dump文件,把大key找出来,再联系业务人员。
在做rdb分析的同时,也考虑到,会不会是有人偷偷连接了实例,然后使用了monitor忘记关掉,于是另外登录到该实例所在的服务器并连接实例后使用client list
命令查看客户端的连接,看是否有带monitor
相关命令的。发现并没有。
~]$ redis-cli -p 9999 client list | grep monitor
~]$
另一方面使用连接实例使用bgsave
命令生成dump数据文件的同事也发现,生成的数据文件的大小只有130多M,分析虽然也分析出来了一个大key,但是大小也只有130多M,是一个拥有360多万个元素的List
。
但是这应该完全不足以造成9个G的内存使用量。我还以为是bgsave命令没正常执行?我又重新执行了一次bgsave命令,查看执行时间和dump数据确认确实是130多M。使用info命令查看实例的信息,也看不出问题。
一筹莫展之际,同事亮哥从实例的client list
命令的结果看出了所以然。
]$ redis-cli -p 9012 client list | grep -v "omem=0"
id=11164727 addr=10.4.7.48:50478 fd=458 name= age=4230 idle=303 flags=c db=0 sub=0 psub=0 multi=-1 qbuf=163072064 qbuf-free=0 obl=0 oll=659943 omem=8546641352 events=rw cmd=lrange
这个被筛选出来的客户端链接,omem
怎么有8个G。omem
是什么值。它是redis服务对客户端连接输出缓存的内存占用量。
查看redis实例的慢日志,可以看到如下的结果,相同List key的lrange查询,参数是0 -1。
经过思考,大概可以这样理解,使用这个缓存的实例有一个List
类型的大key,有360多万个元素,大概是130多M,然后客户端频繁的通过 lrange keyname 0 -1
的方式全量获取所有元素。缓存服务端接收到指令,耗时700000多微秒(700多毫秒)把对应的数据给扔到输出缓冲区中,然后接着处理别的指令去了,然后因为这个指令调用的很频繁,输出缓冲区的数据就越积越多,但客户端接收数据的速度有限。形象点可以理解为一个池子一边接水一边放水,放水速度小于接水速度,接水的就是Redis服务处理指令获取到的结果,放水的就是客户端接收返回结果,这个池子就是输出缓存区,也是要占用Redis实例的内存的,时间足够,池子迟早会满。这也就是Redis实例内存不断增长的原因。
因为Redis实例内的数据的数量并没有改变,所以该实例的Slave实例的内存并没有变化。
回过头来看,如果master实例的内存暴涨,但是slave实例的内存与master实例的内存差距很大的情况下,就很可能是monitor命令未关或者输出缓冲区积压导致的。
最终我们手动将对应的客户端连接kill掉,然后内存唰的一下就降下来了。
~]$ redis-cli -p 9012 client list | grep -v "omem=0"
id=2253936 addr=10.4.7.48:52303 fd=276 name= age=7580 idle=36 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=0 obl=0 oll=1581 omem=20931976 events=rw cmd=lrange
id=2252693 addr=10.4.7.48:51712 fd=252 name= age=9268 idle=230 flags=c db=0 sub=0 psub=0 multi=-1 qbuf=79914221 qbuf-free=0 obl=0 oll=504978 omem=6682230512 events=rw cmd=lrange
id=2258097 addr=10.4.7.48:54497 fd=345 name= age=1172 idle=194 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=0 obl=0 oll=254068 omem=3361306536 events=rw cmd=lrange
id=2257345 addr=10.4.7.48:54063 fd=401 name= age=2438 idle=167 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=0 obl=0 oll=1642 omem=21713784 events=rw cmd=lrange
~]$ redis-cli -p 9012 client kill 10.4.7.48:51712
OK
~]$ redis-cli -p 9012 client kill 10.4.7.48:54497
OK