网易视频云 HBase RegionServer宕机案件侦查

网易视频云:HBaseRegionServer宕机案件侦查

今天网易视频云技术专家给大家分享一下HBase–RegionServer宕机案件侦查，欢迎参与讨论。

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

案件现场篇

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

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

很显然，这种异常最大可能原因就是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

/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)

atsun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:39)

atsun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:223)

atsun.nio.ch.IOUtil.read(IOUtil.java:197)

atsun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:384)

atorg.apache.hadoop.hbase.ipc.RpcServer.channelRead(RpcServer.java:2246)

atorg.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: ClientServicemethodName: 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