从“订单不存在”异常出发，窥探mysql数据库redo日志和binlog的一致性问题
问题缘起
公司的公共订单服务线上有一个场景：上游业务系统监听订单库binlog，如果有新订单产生，那么根据binlog中的订单id字段，来反查订单服务的查询接口，获取该订单的详细信息；
但在该服务上线后，订单服务的报警群里经常能发现一类由于该查询引发的订单不存在异常，然后立刻通过一次重试，又能查到该订单了，最开始的想法是这些查询一定是走到了从库，是由于数据库主从同步延迟的原因，没有查到该订单信息；
失败的修复
基于这个假设，订单服务开放了一个查询主库的接口，在该接口的sql语句里加入强制查询主库的前缀（能通过公司的dbproxy路由到主库），并让该上游业务系统走该接口；但是该流程上线后，并没有发现该类错误有减少；
这就有点出乎意料了：上游系统收到mysql的binlog消息后再去反查主库，此时该条binlog的对应数据，可能会在数据库中还没落盘吗？
数据库内部的两阶段提交
要解答该问题，需要了解mysql的redo日志刷盘以及binlog的产生顺序。首先先简单介绍一下redo日志和binlog日志；
我们知道mysql innodb引擎为了保证事务的持久性，用redo日志做宕机后的数据恢复；而mysql的binlog日志用于数据库的主从数据同步。为了保证两者的一致性，mysql内部用了二阶段提交的方式进行日志和数据的最终刷盘，大致的简化流程如下：
可以看到发起提交事务后主要经过3个阶段：
- redo日志的prepare阶段，在这个阶段innodb会将undo, redo日志进行刷盘；
- binlog的prepare和commit阶段，这里binlog的prepare其实什么也没有做，而在commit的时候刷新binlog到磁盘，在这个时候，其实事务是已经确定要提交了（无论后面是否发生宕机）；
- redo日志的commit阶段，这个时候会清除undo日志，把redo日志刷数据盘，也就是mysql的存储数据真正落库;
如果mysql在这个过程中发生宕机，会以宕机前binlog的commit阶段是否完成作为判断标准，如果该事务的xid已经存在于binlog当中，也就是之前的事务的binlog已经刷到磁盘中，那么会向前恢复，用redo日志进行刷数据盘，继续没有完成的第3步，如果binlog中没有该事务的xid，则进行回滚；所以通过这种redolog和binlog的prepare-commit两阶段提交方式，mysql保证最终刷到磁盘的redolog和binlog的内容是一致的，这两者的一致性也保证了主从数据的一致；
在这个过程中可以看到，binlog是先于事务提交产生的；所以刚才的问题：收到binlog消息再去反查主库，理论上是否会存在查不到数据的情况，答案是肯定的；
case排查
但是这只是一个理论上的可能性，可以从上图看到，在binlog发送之后，整个事务剩下的只有第三步：清除undo日志，并把redo日志刷数据盘；一般一次数据库的操作都是ms内的，而在这个“订单不存在”的异常场景中，上游系统接收到binlog消息并反查数据的过程中，数据链路包含canal, ddmq等中间件，还会经过订单中心服务，耗时会比一次数据库的操作都要少吗？
所以还是需要具体case具体分析：找到报订单不存在的一个订单id，排查该订单所对应的下单日志，发现该下单调用一共用了900多ms，而调用数据库插入订单表就用了700多ms，明显是有异常；于是联系DBA同学，让他们确认下在mysql服务端的实际执行时间，发现确实耗费了这么长的时间，DBA同学反馈如下：
所以基本可以得出是因为磁盘的ioutil利用率有异常的升高，导致数据库偶发出现耗时很长的写入；可以推测，如果ioutils在redo日志的commit阶段异常升高,那么redo日志刷数据盘时会因io堵塞而耗时很久，而此时binlog已经落盘了，上游系统就出现了收到binlog来反查还未提交完成的数据的case，导致订单中心出现“订单不存在”的报错。
验证和总结
后续DBA同学在6月15日进行了主从切换，后续就再也没有出现过因为此类问题而报的订单不存在异常，这从侧面印证了mysql binlog和redo日志的上述二阶段提交流程。
这个问题揭示了在innodb事务的提交过程中，binlog和redolog还是存在短暂不一致的阶段（虽然很短），而在这次的case中，由于机器硬件产生的ioutil异常将这不一致的问题进行了放大，出现了上游业务的查询失败问题，虽然该case最终能通过重试解决，但更好的做法是：对于依赖订单的上游业务系统，应该接入的是订单服务发送的业务消息（如下完单后的订单创建消息），而尽量少依靠底层的binlog消息；