排查redisson中订阅connection无故消失的问题

2016/12/13 20:52:41 No Comments

最近在项目中使用了redis结合spring cache一起作了一个缓存,并使用了订阅功能来达到进程间的数据同步。但在测试使用过程中,发现第二天一来,本来应该工作的订阅同步并不能进行。当时没在意,简单重启了事。但后来发现,每天早上相应的同步都不能进行,并且经测试。每个进程的同步都不进行,感觉是redis的订阅出问题了。

1. 验证问题

表现出来就是A程序修改了数据,B程序并没有识别到这次更新。那么就先尝试手动在redis中进行相应的set操作,因为订阅的是redis的空间事件,即key space event. 在控制台单独连接redis,执行相应的set 命令,在B程序中并没有任何表示。
怀疑是不是redis的发布订阅出问题了,就另开终端,手动地进行订阅,一切正常。
初步确定是程序出问题了。

2. 查看程序

把进程的stack打印一份,查看里面的线程信息,发现并没有redisson的线程信息。一般来说,没收到消息也可能是线程内阻塞了,但是直接就没有相应的线程,这就有问题了。
怀疑是不是相应的连接被断开之后就没有再连,也可能是redis server被重启了。

重新连接redis,使用status查看相应的状态,显示server端并没有重启过,其运行时间长达X天,即没有间断过。

回过来再看相应的redisson程序,里面有一个watch dog,是负责连接断开重连的。即如果连接被断掉了,它会尝试重连,但每一次的重连都会迟后一定时间,如 1 2 4 8 秒这样。这也是为什么要看stack的原因。简单看了下watchdog的实现,表示并没有明显的问题(或者就没问题)。

进一步怀疑是不是出现了某个异常,导致相应的watchdog重连直接被中断了。比如Error级错误。将相应的日志拉下来一份,因为一晚上都没人操作,日志信息本身也很少。直接在里面使用grep Exception查找日志信息,但一切也很正常,甚至没有异常发生。

再重新查看了redisson的源码,里面使用netty的channelInActive来进行重连尝试。在本地测试了一下这个机制,redis重启或者断开连接,它都能检测到。开始怀疑是不是日志信息不全,被吞掉了。重新调整日志级别,将redisson和netty的级别调到TRACE级别,结果中午过去一会,再回来看。相应的连接又不见了,订阅又不能正常工作。查看了日志,里面也没有任何信息,因为这期间无任何操作。

3. 回到redis,查找网络问题

从以上的现象,考虑到这期间没有操作,并且在接近1个多小时后,相应的订阅就不能工作。并且在之前的日志中,发现如果redis中一直有相应的命令产生时,订阅反而是在工作的。这就怀疑是不是网络上的问题,因为没有网络操作,导致连接不明原因被中断,但netty没有探测到。

回到redis server,在确定订阅失效后,想到订阅是在相应的连接上调用psubscribe操作,相应的连接信息是有记录的。本来想从redis server日志中找点东西,但看了配置文件,redis server输出默认是关的。但是可以使用 redis client查看所有连接。使用此命令,把所有连接输出到文件,查找 psub=1的行,结果是没有找到任何记录。这就表示,从server这端来看,已经没有订阅的连接连上来。

但从程序这边日志来看,确又表示没有收到连接被断开的消息。这种现象马上就想到keepalive的类似信息,是不是因为没有keepalive导致连接被默认关掉。因为在订阅断开期间,确实没有任何网络交互(trace日志中没有任何输出). 通过google netty channelInactive和keepalive,结果确实有一些信息表明。如果没有开启keepalive,很有可能根本就不会触发netty的这个回调。

之前对netty有一些了解,一般网络程序都有类似ping/pong处理,在redisson中,并没有在netty中使用ping/pong协议。又看了redis,虽然也有提交类似命令。
重新查看redis.conf的整个配置文件,有2个配置项引起了注意,分别是 timeout 和 tcp-keepalive。将这2个参数,再google了一下,发现此篇文章。

http://rossipedia.com/blog/2014/01/redis-i-like-you-but-youre-crazy/

里面提到了这2个参数对redis的影响以及潜在的问题点。

4. 调整配置,网络keepalive

从配置参数上来看,这个keepalive是工作在tcp层的,应用程序不可见,但仍可以任何保持心跳的一种实现手段。将其配置先都配置为 60,即无操作60秒之后关掉空闲连接,并且每60秒发一次心跳交互。

在配置完之后,查看相应的日志,发现redisson在每60秒之后就会显示收到了connection close的通知而重建connection,以保证在minConnection之上。但是订阅连接并没有收到相应的通知。从server端,通过client list也可以看到,每当idle接近60之后相应的连接即会重新换成新的连接,idle再从0开始计时。但是订阅的连接(最后的cmd为psubscribe)相应的age一直在增加,并且idle也一直在增加,并没有被关闭。

在观察了一晚上之后,第二天再看连接列表,相应的订阅连接的age达到10K级别,即生存了一晚上,并且idle时间也很长,但相应的连接也没有被关闭。在终端在通过set测试了一个数据命令,查看程序日志,马上就能打印出相应的订阅消息,表示整个程序工作正常。也没有问题了。

5. keepalive参数重要性

后来又单独google一下keepalive信息,发现了一些关于tcp方面的一些信息,并且在redisson 15年的一次讨论中,也提到server中的keep-alive配置顶。一并链接如下

LVS和Nginx之间的keepAlive 以及在nginx中设置tcp层keepAlive    http://blog.sina.com.cn/s/blog_e59371cc0102ux5w.html
一个老外控诉redis中的这2个网络参数以及默认设置    http://rossipedia.com/blog/2014/01/redis-i-like-you-but-youre-crazy/
redisson中的连接没有响应以及连接超时的问题讨论    https://github.com/redisson/redisson/issues/198

此次问题的处理过程,走了一些弯路,应该直接从client list入手。但通过此次问题处理,也对网络有更深的了解。同时,进程间的通讯也更加了解。

后面,通过日志监控,发现由于订购命令空间事件太多,会在一定程度上影响到订阅的消费处理,取消了一些短时间对象在redis中的缓存(如30秒级的缓存,订阅事件会收到expired通知和delete通知),当然这跟这次的连接关系不大。

转载请标明出处:i flym
本文地址:https://www.iflym.com/index.php/code/201612130001.html

相关文章:

留下足迹