一、案例
收到用户反馈,最近3天,在20:05-20:10之间阿里MQ部分消息没有消费记录。问为什么?
二、问题
为什么在最近3天,在20:05-20:10之间阿里MQ部分消息没有消费记录呢?
三、收集及分析数据
3.1 收集阿里MQ的后台日志
阿里MQ管理员收集后台日志没有发现异常情况。
3.2 咨询阿里的支持人员
- 建议我们打印更多的程序处理日志
- 收集更多的数据
- 提出一些假设
- 等等
3.3 召集专家会议
召集阿里MQ运维工程师,开发员一起进行问题沟通,并提出以下假设:
- 信息没有投递。
- 信息投递时没有在阿里mq上完成保存。
- 消息消费不成功。
3.4 校验假设
- 信息没有投递,经开发同事确认已经投递成功。
- 信息投递时没有在阿里mq上完成保存,凡是投递到阿里MQ的信息都会先保存到MYSQL上,于是我们根据开发同事提供的消息内容,查询数据库没有记录,可能的原因已经消费了,MQ删除了,也有可能是消息回滚了,MQ删除。这时如果不具备MYSQL的知识的可能就在这里停止了。其实除了查数据库外,我们还可以查MYSQL的binlog追踪目标消息在MYSQL变化轨迹,结果发现真的有这条信息创建时间和删除时间,两者相差了5秒,相比其他消息,足足长了10倍左右。为什么会这样呢,与阿里技术支持交流,发现本地事务变慢都会导致消息回滚的。
查看mysql binlog的内容命令:/usr/bin/mysqlbinlog --no-defaults /var/lib/mysql/mysql-bin.000001 | more
- 于是,我们在APM(CAT)工具上检查,发现最近3天,在20:05-20:10之间数据库上一条简单insert into t1 values()语句竟然花费了5秒左右。通过生成AWR竟然发现log parallel write的延时变长了1倍。
- 为什么变慢了1倍呢?
- 经过分析,怀疑存储变慢了,于是和存储管理员沟通,发现在3天前启动了SVC复制,这个时间正好与MQ消息异常时间点吻合。
- 但是为什么只在20:05-20:10之间发生呢?进一步核查,在该时间段正好有一个处理大批量的后台作业在运行,产生大量的日志,对log parallel write的延时要求好高。结合oracle的原理,这两个条正好凑在一起,造成log file sync 与 log parallel write资源等待与竞争,所以数据库小事务在该时间变慢了,其余时间正常。
四、解决方案
- 停止SVC的复制,MQ消息恢复正常,业务没有发现异常。
- 为什么要停SVC而不是听作业呢?
- 优先级不一样,后台作业相对于SVC的复制,对业务更重要。
- SVC是后来的变更,作业一直都存在,所以
五、总结
- 在交易系统数据库里进行大批量数据处理作业是不合理的,虽然之前没有出现过异常,但是一旦有新增的需求,数据库就变得很脆弱的。
- SVC复制造成LOG FILE 写入延时达1倍,我认为不合理的,无型之中把交易系统的容量降了一半。(不过IBM坚持是合理的)
- 再一次验证海恩发则,多个不合理、异常最终凑在一起,就成为故障了。