软件开发培训学校:解Bug之路-记一次存储故障的排查过程( 二 )


软件开发培训学校:解Bug之路-记一次存储故障的排查过程

文章插图
 只能靠日志分析了既然找不到什么头绪 , 那么只能从日志入手 , 好好分析推理了 。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以及客户端无法创建连接的元凶 。如下面所示:
软件开发培训学校:解Bug之路-记一次存储故障的排查过程

文章插图
 由于app1的commit特别慢而卡住了reactor1线程 , 从而落在reactor1线程上的握手操作都会超时!如下图所示:
软件开发培训学校:解Bug之路-记一次存储故障的排查过程

文章插图
 为什么之前的模拟宕机测试发现不了这一点因为模拟宕机的时候 , 在事务开始的第一条SQL就会报错 , 而执行SQL都是在Worker线程里面 ,  所以并不会触发reactor线程中commit超时这种现象 , 所以测试的时候就遗漏了这一点 。为什么commit会变慢?系统一直跑的好好的 , 为什么突然commit就变慢了呢 , 而且笔者发现 , 这个commit变慢所关联的DB正好也是出现慢SQL的那个DB 。于是笔者立马就去找了DBA,由于我们应用层和数据库层都没有commit时间的监控(因为一般都很快 , 很少出现慢的现象) 。DBA在数据库打的日志里面进行了统计 , 发现确实变慢了 , 而且变慢的时间和我们应用报错的时间相符合! 顺藤摸瓜 , 我们又联系了SA , 发现其中和存储相关的HBA卡有报错!如下图所示:
软件开发培训学校:解Bug之路-记一次存储故障的排查过程

文章插图
 报错时间都是一致的!紧急修复方案由于是HBA卡报错了 , 属于硬件故障 , 而硬件故障并不是很快就能进行修复的 。所以DBA做了一次紧急的主从切换 , 进而避免这一问题 。
软件开发培训学校:解Bug之路-记一次存储故障的排查过程

文章插图
 一身冷汗之前就有慢sql慢慢变多 , 而后突然数据库存储hba卡宕机导致业务不可用的情况 。而这一次到最后主从切换前为止 , 报错越来越频繁 , 感觉再过一段时间,HBA卡过段时间就完全不可用 , 重蹈之前的覆辙了!中间件修复我们在中间件层面将commit和rollback操作挪到Worker里面 。这样 , commit如果卡住就不再会引起创建连接失败这种应用报错了 。总结由于软件层面其实是比较信任硬件的 , 所以在硬件出问题时 , 就会产生很多诡异的现象 , 而且和硬件最终的原因在表面上完全产生不了关联 。只有通过抽丝剥茧 , 慢慢的去探寻现象的本质才会解决最终的问题 。要做到高可用真的是要小心评估各种细节 , 才能让系统更加健壮!作者:无毁的湖光-A


以上关于本文的内容,仅作参考!温馨提示:如遇健康、疾病相关的问题,请您及时就医或请专业人士给予相关指导!

「四川龙网」www.sichuanlong.com小编还为您精选了以下内容,希望对您有所帮助: