解Bug之路-记一次存储故障的排查过程

解Bug之路-记一次存储故障的排查过程

高可用真是一丝细节都不得马虎。平时跑的好好的系统，在相应硬件出现故障时就会引起出潜在的Bug。恰恰这些故障在应用层的表现稀奇古怪，很难让人联想到是硬件出了问题，特别是偶发性出现的问题更难排查。今天，笔者就给你们带来一个存储偶发性故障的排查过程。

Bug现场

咱们的积分应用因为量很是大，因此须要进行分库分表，因此接入了咱们的中间件。一直稳定运行，但应用最近确常常偶发链接创建不上的报错。报错以下:

GetConnectionTimeOutException

而笔者中间件这边收到的确是:

NIOReactor - register err java.nio.channels.CloasedChannelException

这样的告警。整个Bug现场以下图所示:

偶发性错误

以前出过相似register err这样的零星报警，最后缘由是安全扫描，并无对业务形成任何影响。而这一次，相似的报错形成了业务的大量链接超时。因为封网，线上中间件和应用已经稳定在线上跑了一个多月，代码层面没有任何改动！忽然出现的这个错误感受是环境出现了某些问题。并且因为线上的应用和中间件都是集群，出问题时候都不是孤立的机器报错，没道理全部机器都正好有问题。以下图所示:

开始排查是否网络问题

遇到这种链接超时，笔者最天然的想法固然是网络出了问题。因而找网工进行排查，
在监控里面发现网络一直很稳定。并且若是是网络出现问题，同一网段的应用应该也都会报错
才对。事实上只有对应的应用和中间件才报错，其它的应用依旧稳妥当当。

又发生了两次

就在笔者以为这个偶发性问题可能不会再出现的时候，又开始抖了。并且是一个下午连抖了两次。脸被打的啪啪的，算了算了，先重启吧。重启中间件后，觉得能消停一会，没想到半个小时以内又报了。看来今天不干掉这个Bug是下不了班了!

开始排查日志

事实上，笔者一开始就发现中间件有调用后端数据库慢SQL的现象，因为比较偶发，因此将这个现象发给DBA以后就没有继续跟进,DBA也反馈SQL执行没有任何异常。笔者开始认真分析日志以后，发现一旦有 中间件的register err 一定会出现中间件调用后端数据库的sql read timeout的报错。
但这两个报错彻底不是在一个线程里面的，一个是处理前端的Reactor线程，一个是处理后端SQL的Worker线程，以下图所示:

这两个线程是互相独立的，代码中并无发现任何机制能让这两个线程互相影响。难道真是这些机器自己网络出了问题？前端APP失败，后端调用DB超时，怎么看都像网络的问题！

进一步进行排查

既然有DB(数据库)超时，笔者就先看看调用哪一个DB超时吧，毕竟后面有一堆DB。笔者忽然发现，和以前的慢SQL同样，都是调用第二个数据库超时，而DBA那边却说SQL执行没有任何异常，

笔者感受明显SQL执行有问题，只不过DBA是采样并且将采样耗时平均的，偶尔的几笔耗时并不会在总体SQL的耗时里面有所体现。

只能靠日志分析了

既然找不到什么头绪，那么只能从日志入手，好好分析推理了。REACTOR线程和Worker线程同时报错，但二者并没有特殊的关联，说明多是同一个缘由引发的两种不一样现象。笔者在线上报错日志里面进行细细搜索，发如今大量的

NIOReactor-1-RW register err java.nio.channels.CloasedChannelException

日志中会掺杂着这个报错:

NIOReactor-1-RW Socket Read timed out
	at XXXXXX . doCommit
	at XXXXXX Socket read timedout

这一看就发现了端倪，Reactor做为一个IO线程，怎么会有数据库调用呢?因而翻了翻源码，原来，咱们的中间件在处理commit/rollback这样的操做时候仍是在Reactor线程进行的！很明显Reactor线程卡主是因为commit慢了!笔者立马反应过来,而这个commit慢也正是致使了regsiter err以及客户端没法建立链接的元凶。以下面所示:

因为app1的commit特别慢而卡住了reactor1线程，从而落在reactor1线程上的握手操做都会超时！以下图所示:

为何以前的模拟宕机测试发现不了这一点

由于模拟宕机的时候，在事务开始的第一条SQL就会报错，而执行SQL都是在Worker线程里面，
因此并不会触发reactor线程中commit超时这种现象，因此测试的时候就遗漏了这一点。

为何commit会变慢?

系统一直跑的好好的，为何忽然commit就变慢了呢，并且笔者发现，这个commit变慢所关联的DB正好也是出现慢SQL的那个DB。因而笔者立马就去找了DBA,因为咱们应用层和数据库层都没有commit时间的监控(由于通常都很快，不多出现慢的现象)。DBA在数据库打的日志里面进行了统计，发现确实变慢了，并且变慢的时间和咱们应用报错的时间相符合！
顺藤摸瓜，咱们又联系了SA，发现其中和存储相关的HBA卡有报错！以下图所示:

报错时间都是一致的！

紧急修复方案

因为是HBA卡报错了，属于硬件故障，而硬件故障并非很快就能进行修复的。因此DBA作了一次紧急的主从切换，进而避免这一问题。

一身冷汗

以前就有慢sql慢慢变多，然后忽然数据库存储hba卡宕机致使业务不可用的状况。
而这一次到最后主从切换前为止，报错愈来愈频繁，感受再过一段时间,HBA卡过段时间就彻底不可用，重蹈以前的覆辙了！

中间件修复

咱们在中间件层面将commit和rollback操做挪到Worker里面。这样，commit若是卡住就再也不会引发建立链接失败这种应用报错了。

总结

因为软件层面实际上是比较信任硬件的，因此在硬件出问题时，就会产生不少诡异的现象，并且和硬件最终的缘由在表面上彻底产生不了关联。只有经过抽丝剥茧，慢慢的去探寻现象的本质才会解决最终的问题。要作到高可用真的是要当心评估各类细节，才能让系统更加健壮！

公众号

关注笔者公众号，获取更多干货文章: