2018-08-14 KK日记，阿里MQ消息异常回滚排查——原因：本地数据库事务变慢。

一、案例

收到用户反馈，最近3天，在20：05-20：10之间阿里MQ部分消息没有消费记录。问为什么？

二、问题

为什么在最近3天，在20：05-20：10之间阿里MQ部分消息没有消费记录呢？

三、收集及分析数据

3.1 收集阿里MQ的后台日志

阿里MQ管理员收集后台日志没有发现异常情况。

3.2 咨询阿里的支持人员

• 建议我们打印更多的程序处理日志
• 收集更多的数据
• 提出一些假设
• 等等

3.3 召集专家会议

召集阿里MQ运维工程师，开发员一起进行问题沟通，并提出以下假设：

1. 信息没有投递。
2. 信息投递时没有在阿里mq上完成保存。
3. 消息消费不成功。

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坚持是合理的）
• 再一次验证海恩发则，多个不合理、异常最终凑在一起，就成为故障了。