HBase问题诊断 – RegionServer宕机

本文涉及的产品
日志服务 SLS,月写入数据量 50GB 1个月
简介:

本来静谧的晚上,吃着葡萄干看着球赛,何等惬意。可偏偏一条报警短信如闪电一般打破了夜晚的宁静,线上集群一台RS宕了!于是倏地从床上坐起来,看了看监控,瞬间惊呆了:单台机器的读写吞吐量竟然达到了5w ops/sec!RS宕机是因为这么大的写入量造成的?如果真是这样,它是怎么造成的?如果不是这样,那又是什么原因?各种疑问瞬间从脑子里一一闪过,甭管那么多,先把日志备份一份,再把RS拉起来。接下来还是Bug排查老套路:日志、监控和源码三管齐下,来看看到底发生了什么!

案件现场篇

下图是使用监控工具Ganglia对事发RegionServer当时读写吞吐量的监控曲线,从图中可以看出,大约在19点~21点半的时间段内,这台RS的吞吐量都维持了3w ops/sec左右,峰值更是达到了6w ops/sec。之前我们就线上单台RS能够承受的最大读写吞吐量进行过测定,基本也就维持在2w左右,主要是因为网络带宽瓶颈。而在宕机前这台RS的读写吞吐量超出这么多,直觉告诉我RS宕机原因就是它!


接着就赶紧把日志拉出来看,满屏的responseTooSlow,如下图所示:

002

很显然,这种异常最大可能原因就是Full GC,果然,经过耐心地排查,可以看到很多如下所示的Full GC日志片段:

2016-04-14 21:27:13,174 WARN  [JvmPauseMonitor] util.JvmPauseMonitor: Detected pause in JVM or host machine (eg GC): pause of approximately 20542ms
GC pool 'ParNew' had collection(s): count=1 time=0ms
GC pool 'ConcurrentMarkSweep' had collection(s): count=2 time=20898ms
2016-04-14 21:27:13,174 WARN  [regionserver60020.periodicFlusher] util.Sleeper: We slept 20936ms instead of 100ms, 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

可以看出,HBase执行了一次CMS GC,导致整个进程所有线程被挂起了20s。通过对MemStore的监控也可以看出这段时间GC力度之大,如下图所示:


GC时间长最明显的危害是会造成上层业务的阻塞,通过日志也可以看出些许端倪:

java.io.IOException: Connection reset by peer
        at sun.nio.ch.FileDispatcherImpl.read0(Native Method)
        at sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:39)
        at sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:223)
        at sun.nio.ch.IOUtil.read(IOUtil.java:197)
        at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:384)
        at org.apache.hadoop.hbase.ipc.RpcServer.channelRead(RpcServer.java:2246)
        at org.apache.hadoop.hbase.ipc.RpcServer$Connection.readAndProcess(RpcServer.java:1496)
....
2016-04-14 21:32:40,173 WARN  [B.DefaultRpcServer.handler=125,queue=5,port=60020] ipc.RpcServer: RpcServer.respondercallId: 7540 service: ClientService methodName: Multi size: 100.2 K connection: 10.160.247.139:56031: output error
2016-04-14 21:32:40,173 WARN  [B.DefaultRpcServer.handler=125,queue=5,port=60020] ipc.RpcServer: B.DefaultRpcServer.handler=125,queue=5,port=60020: caught a ClosedChannelException, this means that the server was processing a request but the client went away. The error message was: null

上述日志表示HBase服务端因为Full GC导致一直无法响应用户请求,用户客户端程序在一定时间过后就会SocketTimeout并断掉此Connection。连接断掉之后,服务器端就会打印如上日志。然而,这些和我们的终极目标好像并没有太大关系,别忘了我们的目标是找到RS宕机的原因哦!

破案铺垫篇

经过对案件现场的排查,唯一有用的线索就是HBase在宕机前经历了很严重、很频繁的Full GC,从下面日志可以进一步看出,这些Full GC都是在 concurrent mode failure模式下发生的,也就是虚拟机还未执行完本次GC的情况下又来了大量数据导致JVM内存不够,此时虚拟机会将所有用户线程挂起,执行长时间的Full GC!

(concurrent mode failure): 45876255K->21800674K(46137344K), 10.0625300 secs] 48792749K->21800674K(49283072K), [CMS Perm : 43274K->43274K(262144K)], 10.2083040 secs] [Times: user=12.02 sys=0.00, real=10.20 secs]
2016-04-14 21:22:43,990 WARN  [JvmPauseMonitor] util.JvmPauseMonitor: Detected pause in JVM or host machine (eg GC): pause of approximately 10055ms
GC pool 'ParNew' had collection(s): count=2 time=244ms
GC pool 'ConcurrentMarkSweep' had collection(s): count=1 time=10062ms

上文提到Full GC会对上层业务产生很严重的影响,那有没有可能会对下层依赖方也产生很大的影响呢?事实是Yes!而且,RS宕机的大部分原因也要归咎于此!

进一步查看日志,发现HBase日志中出现下述异常:

2016-04-14 21:22:44,006 WARN  [ResponseProcessor for block BP-632656502-10.160.173.93-1448595094942:blk_1073941840_201226] hdfs.DFSClient: DFSOutputStream ResponseProcessor exception  for block BP-632656502-10.160.173.93-1448595094942:blk_1073941840_201226
java.io.IOException: Bad response ERROR for block BP-632656502-10.160.173.93-1448595094942:blk_1073941840_201226 from datanode 10.160.173.93:50010
at org.apache.hadoop.hdfs.DFSOutputStream$DataStreamer$ResponseProcessor.run(DFSOutputStream.java:732)

从日志内容来看应该是hbase调用DFSClient向datanode写入block数据”BP-632656502-10.160.173.93-1448595094942:blk_1073941840_201226″,但是datanode返回失败。具体失败原因需要查看datanode节点日志,如下所示:

2016-04-14 21:22:43,789 INFO org.apache.hadoop.hdfs.server.datanode.DataNode: opWriteBlock BP-632656502-10.160.173.93-1448595094942:blk_1073941840_201226 received exception java.net.SocketTimeoutException: 10000 millis timeout while waiting for channel to be ready for read. ch : java.nio.channels.SocketChannel[connected local=/10.160.173.94:50010 remote=/10.160.173.94:30110]

2016-04-14 21:22:43,779 ERROR org.apache.hadoop.hdfs.server.datanode.DataNode: hz-hbase4.photo.163.org:50010:DataXceiver error processing WRITE_BLOCK operation  src: /10.160.173.94:30123 dest: /10.160.173.94:50010
java.net.SocketTimeoutException: 10000 millis timeout while waiting for channel to be ready for read. ch : java.nio.channels.SocketChannel[connected local=/10.160.173.94:50010 remote=/10.160.173.94:30123]

很显然,从日志可以看出,datanode一直在等待来自客户端的read请求,但是直至SocketTimeout,请求都没有过来,此时datanode会将该连接断开,导致客户端收到上述”Bad response ERROR ***”的异常。

那这和Full GC有什么关系呢?很简单,就是因为Full GC导致HBase所有内部线程挂起,因此发往datanode的read请求也被挂起了,datanode就等啊等,左等右等都等不到,万不得已才将连接断掉。

查看Hadoop客户端源码可知,如果DFSClient发生上述异常,DFSClient会将一个全局标志errorIndex设为一个非零值。具体可参见DFSOutputStream类中如下代码片段:


004


破案结局篇

上述铺垫篇最后的结果就是Hadoop客户端会将一个全局标志errorIndex设为一个非零值,那这到底和最终RS宕掉有什么关系呢?来继续往下看。下图HBase日志相关片段截图,记录了比较详细的RS宕机异常信息,我们就以这些异常信息作为切入点进行分析,可以看出至少三条有用的线索,如下图所示:



005

线索一:RS宕机最直接的原因是因为系统在关闭LogWriter(之后会重新开启一个新的HLog)的时候失败

线索二:执行LogWriter关闭失败的原因是”writing trailer”时发生IOException异常

线索三:而发生IOException异常的原因是”All datanodes *** are bad”

到这里为止,我们能够获得的最靠谱的情报就是RS宕机本质是因为”All datanodes *** are bad”造成的,看字面意思就是这台datanode因为某种原因坏掉了,那我们赶紧去看看datanode的日志,看看那个时间段有没有相关的异常或者错误日志。

然而很遗憾,datanode日志在那个时间点没有打印任何异常或者错误日志,而且显示所有服务都正常,信息如下所示:

2016-04-14 21:32:38,893 INFO org.apache.hadoop.hdfs.server.datanode.DataNode.clienttrace: src: 127.0.0.1, dest: 127.0.0.1, op: REQUEST_SHORT_CIRCUIT_FDS, blockid: 1073941669, srvID: DS-22834907-10.160.173.94-50010-1448595406972, success: true
2016-04-14 21:32:38,894 INFO org.apache.hadoop.hdfs.server.datanode.DataNode.clienttrace: src: 127.0.0.1, dest: 127.0.0.1, op: REQUEST_SHORT_CIRCUIT_FDS, blockid: 1073941669, srvID: DS-22834907-10.160.173.94-50010-1448595406972, success: true
...

看到这里,是不是有点蒙圈:HBase日志里面明明打印说这台datanode坏掉了,但是实际datanode日志显示服务一切正常。这个时候就得翻翻源码了,看看HBase在哪里打印的”All datanodes *** are bad“,通过查看源码,可以看出最终元凶就是上文提到的errorIndex,如下图所示:

006

终于拨开天日了,再不完结就要晕了!上文铺垫篇铺垫到最后就得出来因为Full GC最终导致DFSClient将一个全局标志errorIndex设为一个非零值,在这里终于碰头了,简直泪流满面!

案件梳理篇

整个流程走下来本人都有点晕晕的,涉及的方方面面太多,因此有必要把整个流程完整的梳理一遍,下面简单画了一个示意图:



007

经过对整个案件的整理分析,一方面再次锻炼了如何通过监控、日志以及源码定位排查问题的功底,另一方面在HBase运维过程中也需要特别关注如下几点:

1. Full GC不仅会严重影响上层业务,造成业务读写请求的卡顿。另外还有可能造成与HDFS之间数据请求的各种异常,这种异常严重的时候甚至会导致RegionServer宕机。

2. 上文中提到Full GC基本是由于Concurrent Mode Failure造成,这种Full GC场景比较少见,通常可以通过减小 JVM 参数XX:CMSInitiatingOccupancyFraction来避免,这个参数用来设置CMS垃圾回收时机,假如此时设置为60,表示JVM内已使用内存占到总内存的60%的时候就会进行垃圾回收,减少该值可以使得垃圾回收更早进行

3. 一定要严格限制业务层面的流量。一方面需要和业务方交流,由业务方进行限制,另一方面可以探索HBase业务资源隔离的新方案;


本文转载自:http://hbasefly.com

原文链接

相关实践学习
lindorm多模间数据无缝流转
展现了Lindorm多模融合能力——用kafka API写入,无缝流转在各引擎内进行数据存储和计算的实验。
云数据库HBase版使用教程
  相关的阿里云产品:云数据库 HBase 版 面向大数据领域的一站式NoSQL服务,100%兼容开源HBase并深度扩展,支持海量数据下的实时存储、高并发吞吐、轻SQL分析、全文检索、时序时空查询等能力,是风控、推荐、广告、物联网、车联网、Feeds流、数据大屏等场景首选数据库,是为淘宝、支付宝、菜鸟等众多阿里核心业务提供关键支撑的数据库。 了解产品详情: https://cn.aliyun.com/product/hbase   ------------------------------------------------------------------------- 阿里云数据库体验:数据库上云实战 开发者云会免费提供一台带自建MySQL的源数据库 ECS 实例和一台目标数据库 RDS实例。跟着指引,您可以一步步实现将ECS自建数据库迁移到目标数据库RDS。 点击下方链接,领取免费ECS&RDS资源,30分钟完成数据库上云实战!https://developer.aliyun.com/adc/scenario/51eefbd1894e42f6bb9acacadd3f9121?spm=a2c6h.13788135.J_3257954370.9.4ba85f24utseFl
相关文章
|
存储 运维 监控
分布式数据库HBase的重要机制和原理的宕机恢复和故障处理
HBase是一个分布式数据库系统,支持高可用性、高性能和高伸缩性。在分布式环境中,数据的分布式存储和管理是非常重要的。HBase通过分布式存储和管理数据来实现高可用性和高性能。同时,HBase还提供了一些重要的机制和原理来支持宕机恢复和故障处理。
453 1
|
分布式计算 Hadoop 分布式数据库
因为主机时间不同步导致的hbase zookeeper 节点宕机奔溃 一例
前几天 ,升级hadoop/hbase 集群, 新 添加了几十台机器, 硬件部门,安装好主机os 后就交付给我们了, 安装好软件环境,配置好,就启动接入集群了,运行了一个礼拜,系统运行正常。 昨天的时候淘汰一台旧机器,上面跑了zookeeper , 需要准备一个新的zookeeper 节点来代替,如实就找了一台hbase 节点上启动了zookeeper 这个时候问题来了, zookeeper 启动后总是在报错, 一直在确定自己的状态。
667 0
|
分布式数据库 Hbase
|
缓存 Java 分布式数据库
排查HBase内存泄漏导致RegionServer挂掉问题
问题描述 在测试Phoenix稳定性时,发现HBase集群其中一台RegionServer节点FullGC严重,隔一段时间就会挂掉。 HBase集群规格       初步分析 使用jstat监控RegionServer的Heap Size和垃圾回收情况 Old区内存一直在90%多,且FullGC次数一直在增多。
2111 0
|
Java 分布式数据库 Apache
|
分布式数据库 Hbase
zookeeper的maxSessionTimeout默认值导致hbase regionserver超时
zookeeper的maxSessionTimeout默认值导致hbase regionserver超时 在hbase中经常会遇到regionserver挂掉的情况,查看日志会看到这样的错误信息 2016-02-16 11:51:24,882 WARN  [master/hadoop02/192.
2916 0
|
3月前
|
分布式计算 Java Hadoop
java使用hbase、hadoop报错举例
java使用hbase、hadoop报错举例
112 4
|
2月前
|
分布式计算 Hadoop Shell
Hadoop-35 HBase 集群配置和启动 3节点云服务器 集群效果测试 Shell测试
Hadoop-35 HBase 集群配置和启动 3节点云服务器 集群效果测试 Shell测试
77 4