记录一次由于redis异常,导致MQ消息消费线程锁定生产问题排查

345 阅读5分钟

生产问题

服务消息队列出现消息长时间未消费情况,猜测可能出现进程异常退出或线程假死。

问题排查记录

1, 通过协调运维人员检查java进程,确定服务对应的进程都存在。

2, 查看服务对应日志,发现162、87服务器上服务对应日志仍有数据在处理,确定服务此时有线程在处理数据。

3, 通过MQ偏移量查询,发现MQ队列中多数队列在16:05后不在进行消费,仅有87服务器对应的2个消息队列存在消费,162服务上消息队列均没有消费,此情况与上一步查询服务日志分析结果相互冲突,进而进行162服务器中服务对应线程状态查询,进一步进行分析。

4, 通过运维人员对162服务器当时服务进程进行dump,通过分析日志发现服务中对应消息消费线程均处于wating状态,触发消息消费线程进行wating状态的是一部分是由于服务从jedis连接池获取连接异常导致的,另一部分通过验证是消息消费线程未从消息队列中获取到消息,进而进入wating状态等待消息队列中进入消息。

5, 与运维人员沟通后,确认16:05时,redis服务有出现异常。

问题排查结果

在以MQ消息偏移量统计为主要依据情况下,通过对现有的日志进行分析,确定由于redis服务在16:05时出现异常服务中在此时并发从jedis连接池获取redis连接异常,导致部分消息消费线程锁定进而进入wating状态,待获取到redis连接进行唤醒,这部分消费线程将不再消费消息,其他一部分线程是由于未从消息队列中获取到消息进而进入wating状态,等待消息队列内进行消息在唤醒。

遗留问题

1、 消费线程进入wating状态后,是否还会消费消息

2、 单一消费线程活动时,全部消费队列是否会有消息进行消费

问题处理方式

为尽快恢复生产,优先将服务进行重启,遗留问题在测试环境进行验证。

相关截图:

服务对应日志截图:

162服务日志

MQ偏移量检查

JDK线程日志分析:从日志中可以确认编号为8、10的消费线程由于并发获取redis连接异常进入wating状态,而编号1、5的消费线程由于未获取到消息而进入wating状态。

遗留问题验证

1,消费线程进入wating状态后,消息队列是否还会进行消费

前置条件:

参考jedis连接池获取连接方式,在消息队列消费线程业务逻辑中手动调用LockSupport.park()方法,使得线程进入wating状态。

结果:

消息队列通过park方法进行wating状态后,消息队列不在有消息被消费。

验证步骤:

1开始消费消息,状态为RUNNABLE

2,代码中写死调用park方法

3,定时任务查询消费线程状态,所有状态为waiting。

4,查询消息队列中偏移量

2,手动恢复一个消息消费线程,所有消费消费队列是否都有消息被消费。

前置条件:

消息队列消费线程业务逻辑中手动调用LockSuppor.park()方法,使得线程进入wating状态,通过定时任务,手动调用LockSupport.unpark(thread)方法将ComsumeMessageThread-1线程唤醒,

结果:

通过手动恢复后的ComsumeMessageThread-1线程会对20个messagequeue中的消息进行消费且偏移量会进行减少,与1月6号生产情况不一致。

在完成所有队列消息消费后, ComsumeMessageThread-1线程进入wating状态,此时线程dump日志中 ComsumeMessageThread-1日志与前面生产线程dump日志中编号1、5的线程日志一致,说明当时162服务的确有消费线程在消费消息,当时提供的MQ偏移量统计截图可能数据更新不及时。

验证步骤:

1开始消费消息,状态为RUNNABLE

2,代码中写死调用park方法

3,定时任务手动调用unpark方法,将consumeMessageThread_1线程唤醒。

4, 查询消息队列中偏移量,多个队列的偏移量均发生变化。

5、当所有队列消息消费结束后,进行线程日志dump,明确consumeMessageThread_1当前wating状态日志与生产日志中编号1、5线程日志一致,进一步确定生产中1、5线程当时是由于未获取到消息而进入wating状态。

最终结论

1, 由于redis服务异常,导致服务在16:05出现消费线程因获取redis连接异常进而锁定,进入wating状态,redis服务恢复后,前面锁定的线程会被解锁,但是消费线程仍存在因并发获取redis连接导致锁定的几率。

2, 通过测试环境验证及生产服务日志分析后、当时提供的生产MQ偏移量统计截图可能数据更新不及时。