国庆期间,HBase集群出现一次比较严重的问题,故障期间,业务方反馈查询大量超时,由于涉及重点业务查询,影响也是比较大的。下面复盘一下问题发生过程并作相应分析

一、问题描述

10月6号傍晚从18:00点开始,业务陆续反馈查询HBase历史数据异常,出现大量超时,下面是当时的业务成功率曲线。整个过程经历了5次成功率下降的阶段,这是之前未出现过的。
图1. 业务成功率曲线

在查看重点业务组所在机器的写监控曲线,故障期间重点表基本不可写:
图2.重点表写曲线

同时重点表的读也是异常的,基本不可读:
图3.重点表读曲线

二、原因分析

2.1 采集分析

查看数据采集曲线,未看到有表数据发生延迟采集或DB数据源故障情况,排除采集异常。

2.2 消费分析

查看数据消费曲线,发现重点业务的所有表消费曲线延迟严重,消费者本身无报错产生,查看消费日志写得很慢,既然消费未报错又写得慢,问题应该出现在HBase端。

2.3 HBase分析

2.3.1 第一次&第二次异常原因分析

根据经验,HBase读写异常很大程度上和机器异常有关。首先,找出重点业务所在的机器列表,并根据所采集的监控曲线,看了下这些机器的处理时耗,如下图所示:
图4.机器处理时耗
从图中,可看出在故障期间,这些机器的处理时耗异常,是所有机器都异常还是只有个别机器处理异常呢,继续从上面图查看分布状态图,如下图所示:
图5.单机处理时耗
从图可以看出,确实有一台机器的处理时耗比其它机器都高,找到异常机器后,从tnm2上看了下单机性能情况,如下图所示:
图6.单机性能曲线
从图中,可以看出,异常机器在18:00附近各项指标也是异常的,磁盘IO、CPU负载、SWAP内存都表现异常,说明机器确实存在问题。那是什么原因导致的机器负载异常呢,继续登陆机器查看日志情况,在18:00附近左右,找到如下一个异常:
图7.异常机器日志异常
从多个异常描述中,都发现一个共性现象,就是集中在t_tcbankroll_list_auid_201707这个表上,看日志信息是这个表在作合并,查看了下合并任务,发现确实在这天有一条合并定时任务,合并任务主要是合并3个月前的表,正好是上述7月份的表,是不是合并存在异常呢,继续看了下监控中关于该异常IP的合并队列,发现在18:00合并队列高达59000,即有几万个合并任务等着被执行,之后合并队列表现异常,机器读写也异常,说明确实合并有问题。
图8.异常机器合并队列
为什么合并会有问题呢?进一步看了下异常表的region的大小,发现大小严重不均,集中在两个端,8G和20G左右。合并出问题应该是出在合并20G大小的region时出现的问题。
图9.异常表region文件数
是在合并哪个Region的时候出的问题呢,再看下图7中异常机器的日志,发现324c091cfd8e944507ae645ddeda78e2这个region合并时出的问题,同时这个region的大小在图9中正好属于20G那个范围的,验证了上述猜想。
那为什么合并大Region过程出现问题了呢,再从18:00异常时间点附近看了下日志,如下所示

1
2
3
4
2017-10-06 18:22:36,280 WARN [regionserver60020] util.Sleeper: We slept 24555ms instead of 3000ms, this is likely due to a long garbage collecting pause and it's usually bad, see,http://hbase.apache.org/book.html#trouble.rs.runtime.zkexpired
2017-10-06 18:22:36,280 WARN [JvmPauseMonitor] util.JvmPauseMonitor: Detected pause in JVM or host machine (eg GC): pause of approximately 22680ms
GC pool 'ParNew' had collection(s): count=1 time=247ms
GC pool 'ConcurrentMarkSweep' had collection(s): count=1 time=22712ms

这种迹象很明显就是在作FullGC,频繁的GC过程阻塞了读写进程, 在这个时间段内,看了下JVM堆内存的使用量,发现异常的高,如下所示:
图10.异常机器JVM堆内存使用
了解FullGC的人都知道,FullGC期间,集群读写会被堵塞,如图7所示客户端连接会出现超时异常,再加上我们机器本身性能比较差,导致FullGC过程中,机器IO、网络、CPU、内存和SWAP等都出现异常,阻塞了集群读写,影响了重点业务的查询。知道啥原因后,直接把机器剔除停掉regionserver进程,业务读写开始恢复正常。

好景不长,只过了不到20min, 第二次异常突然降临,在18点56时,业务查询成功率又开始降低。回想一下第一次故障,只是把当时有异常的机器剔除,但没考虑的是异常表的合并任务并未终结,只是把合并异常的任务转移到其它机器,重点业务组机器并未终止合并,即其它机器的负载并未得到有效缓解,看监控曲线发现,此时另一台机器出现异常,如图10所示,该机集群处理时耗明显高于其它机器,和第一次样,把异常机器剔除后业务恢复正常。
图11.异常机器时耗曲线

2.3.2 第三次&第四次&第五次故障分析

前面2次的故障还好,都还是单机异常所致,后面出现的两次异常却是多机同时出现异常,此时单纯剔除单台机器已无法解决问题,因重点业务组所在机器数量比较少,再重新扩机器进去也不太可行,如果都剔除那读写就完全中止了,影响更大。
上面说到,其实前两次故障都没解决合并异常的本质问题,合并还在继续,合并队列也维持在一个高位,此时对整个机器组来说压力都是非常大的,机器资源大量被用于作合并,导致其它操作无法有效获取资源。只能想其它办法解决。
既然合并队列一直在高位,有什么办法可以降低合并队列长度呢,社区HBase-17928补丁给我们带来了福音,它要解决的就是当表合并异常或在很长时间合并都未完成的场景。使用方式如下:

1
clear_queues 'SERVERNAME', ['QUEUE_NAME1','QUEUE_NAME2']

其中,SERVERNAME表示regionserver,形式如ip,port,timestamp,QUEUE_NAME表示队列的长度,可以为short,long。对于我们来说,采用的是直接清理到机器的合并队列,即如果机器10.x.x.x有问题,清理如下:

1
clear_queues '10.x.x.x,60020,1491511804929'

在清理部分合并队列过长的机器之后,集群读写恢复了部分,但还未全部恢复,导致了第四次业务查询还是受影响,因为清理时没把所有机器清理干净,所以异常还未完全解决。
第四次故障之后,对剩下的机器也全部清理了一遍队列,同时还作了一个操作,就是把异常表移出重点业务组,让合并在组外的机器进行,这样能尽量避免异常表对其它表影响。

在做完上述动作之后,隔了不到10min, 第5次故障又如期而至,充分验证了墨菲定律,不想发生的偏要发生。第5次故障是什么原因呢,从监控曲线上面看,根据第一次和第二次的故障分析,总结出此次也是因单机故障引起的,首先做的就是剔除该异常机器,但因负载问题,一直登录异常,耽误了异常恢复原因,等剔除后业务终于开始恢复正常。

在观察一段时间后,整个重点业务组暂时运行稳定,此时因踢掉了多台机器,组内的10几台机器的region已经分布不均,有潜在风险,需要考虑把之前剔除机器上的region还原。正常的还原方法是,如果regionserver剔除是按正规流程剔除的话,会记录该机器上有什么region,然后机器恢复后把region再move回来即可;不过,像我们这种情况,属于紧急剔除,踢之前没考虑记录region信息,需要考虑从其它渠道来恢复信息,还有一种方法是从日志恢复,日志恢复方法就是从master上去找剔除时间点开始往后带关键字如Transition和Offline等关键字的日志,然后找出region move回到原机器即可。

三、故障梳理

经过上述一系列的分析和采取的一系列措施,故障得以恢复,整个故障原因总结如下:

  • 合并任务异常,触发机器频繁GC,机器负载异常
  • GC阻塞了DFSClient的读写请求发送
  • HDFS服务端报大量的读写Socket连接超时并关闭client请求连接

故障措施总结:

  • 剔除异常机器regionserver进程
  • 清理异常机器的合并队列
  • 恢复region回原机器

四、故障反思

此次故障引发的连锁反应之前也没遇到过,耽误了很多时间,也侧面反应出自己对这些异常缺乏足够的认识,通过此次排查也让自己对regionserver异常有一个更清楚的了解,后续在运维过程中需要更多关注以下一些点:

  • 出现异常,以业务恢复为先,先保留事故现场日志,该剔除的剔除
  • 监控完善,一直在说监控问题,但监控事项总有些纰漏,需在这块优化加强,尤其是巡检机制
  • 业务重点表隔离细化,虽然已经做了相应隔离,但分级还是不够细化,需针对重点业务再作分级隔离