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

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

1. 验证问题

表现出来就是A程序修改了数据&＃xff0c;B程序并没有识别到这次更新。那么就先尝试手动在redis中进行相应的set操作&＃xff0c;因为订阅的是redis的空间事件&＃xff0c;即key space event. 在控制台单独连接redis&＃xff0c;执行相应的set 命令&＃xff0c;在B程序中并没有任何表示。

怀疑是不是redis的发布订阅出问题了&＃xff0c;就另开终端&＃xff0c;手动地进行订阅&＃xff0c;一切正常。

初步确定是程序出问题了。

2. 查看程序

把进程的stack打印一份&＃xff0c;查看里面的线程信息&＃xff0c;发现并没有redisson的线程信息。一般来说&＃xff0c;没收到消息也可能是线程内阻塞了&＃xff0c;但是直接就没有相应的线程&＃xff0c;这就有问题了。

怀疑是不是相应的连接被断开之后就没有再连&＃xff0c;也可能是redis server被重启了。

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

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

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

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

3. 回到redis&＃xff0c;查找网络问题

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

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

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

之前对netty有一些了解&＃xff0c;一般网络程序都有类似ping/pong处理&＃xff0c;在redisson中&＃xff0c;并没有在netty中使用ping/pong协议。又看了redis&＃xff0c;虽然也有提交类似命令。

重新查看redis.conf的整个配置文件&＃xff0c;有2个配置项引起了注意&＃xff0c;分别是 timeout 和 tcp-keepalive。将这2个参数&＃xff0c;再google了一下&＃xff0c;发现此篇文章。

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

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

4. 调整配置&＃xff0c;网络keepalive

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

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

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

5. keepalive参数重要性

后来又单独google一下keepalive信息&＃xff0c;发现了一些关于tcp方面的一些信息&＃xff0c;并且在redisson 15年的一次讨论中&＃xff0c;也提到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

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

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

相关文章&＃xff1a;

作者&＃xff1a; flym

I am flym,the master of the site:)查看flym的所有文章