網(wǎng)易視頻云HBaseRegionServer宕機(jī)案件偵查

網(wǎng)易視頻云:HBaseRegionServer宕機(jī)案件偵查今天網(wǎng)易視頻云技術(shù)專家給大家分享一下HBase–RegionServer宕機(jī)案件偵查，歡迎參與討論。本來(lái)靜謐的晚上，吃著葡萄干看著球賽，何等愜意。可偏偏一條報(bào)警短信如閃電一般打破了夜晚的寧?kù)o，線上集群一臺(tái)RS宕了！于是倏地從床上坐起來(lái)，看了看監(jiān)控，瞬間驚呆了：?jiǎn)闻_(tái)機(jī)器的讀寫吞吐量竟然達(dá)到了5wops/sec！RS宕機(jī)是因?yàn)檫@么大的寫入量造成的？如果真是這樣，它是怎么造成的？如果不是這樣，那又是什么原因？各種疑問(wèn)瞬間從腦子里一一閃過(guò)，甭管那么多，先把日志備份一份，再把RS拉起來(lái)。接下來(lái)還是Bug排查老套路：日志、監(jiān)控和源碼三管齊下，來(lái)看看到底發(fā)生了什么！案件現(xiàn)場(chǎng)篇下圖是使用監(jiān)控工具Ganglia對(duì)事發(fā)RegionServer當(dāng)時(shí)讀寫吞吐量的監(jiān)控曲線，從圖中可以看出，大約在19點(diǎn)~21點(diǎn)半的時(shí)間段內(nèi)，這臺(tái)RS的吞吐量都維持了3wops/sec左右，峰值更是達(dá)到了6wops/sec。之前我們就線上單臺(tái)RS能夠承受的最大讀寫吞吐量進(jìn)行過(guò)測(cè)定，基本也就維持在2w左右，主要是因?yàn)榫W(wǎng)絡(luò)帶寬瓶頸。而在宕機(jī)前這臺(tái)RS的讀寫吞吐量超出這么多，直覺(jué)告訴我RS宕機(jī)原因就是它！接著就趕緊把日志拉出來(lái)看，滿屏的responseTooSlow，如下圖所示：很顯然，這種異常最大可能原因就是FullGC，果然，經(jīng)過(guò)耐心地排查，可以看到很多如下所示的FullGC日志片段：2016-04-1421:27:13,174WARN[JvmPauseMonitor]util.JvmPauseMonitor:DetectedpauseinJVMorhostmachine(egGC):pauseofapproximately20542msGCpool'ParNew'hadcollection(s):count=1time=0msGCpool'ConcurrentMarkSweep'hadcollection(s):count=2time=20898ms2016-04-1421:27:13,174WARN[regionserver60020.periodicFlusher]util.Sleeper:Weslept20936msinsteadof100ms,thisislikelyduetoalonggarbagecollectingpauseandit'susuallybad,see/book.html#trouble.rs.runtime.zkexpired可以看出，HBase執(zhí)行了一次CMSGC，導(dǎo)致整個(gè)進(jìn)程所有線程被掛起了20s。通過(guò)對(duì)MemStore的監(jiān)控也可以看出這段時(shí)間GC力度之大，如下圖所示：GC時(shí)間長(zhǎng)最明顯的危害是會(huì)造成上層業(yè)務(wù)的阻塞，通過(guò)日志也可以看出些許端倪：java.io.IOException:Connectionresetbypeeratsun.nio.ch.FileDispatcherImpl.read0(NativeMethod)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-1421:32:40,173WARN[B.DefaultRpcServer.handler=125,queue=5,port=60020]ipc.RpcServer:RpcServer.respondercallId:7540service:ClientServicemethodName:Multisize:100.2Kconnection:39:56031:outputerror2016-04-1421:32:40,173WARN[B.DefaultRpcServer.handler=125,queue=5,port=60020]ipc.RpcServer:B.DefaultRpcServer.handler=125,queue=5,port=60020:caughtaClosedChannelException,thismeansthattheserverwasprocessingarequestbuttheclientwentaway.Theerrormessagewas:null上述日志表示HBase服務(wù)端因?yàn)镕ullGC導(dǎo)致一直無(wú)法響應(yīng)用戶請(qǐng)求，用戶客戶端程序在一定時(shí)間過(guò)后就會(huì)SocketTimeout并斷掉此Connection。連接斷掉之后，服務(wù)器端就會(huì)打印如上日志。然而，這些和我們的終極目標(biāo)好像并沒(méi)有太大關(guān)系，別忘了我們的目標(biāo)是找到RS宕機(jī)的原因哦！破案鋪墊篇經(jīng)過(guò)對(duì)案件現(xiàn)場(chǎng)的排查，唯一有用的線索就是HBase在宕機(jī)前經(jīng)歷了很嚴(yán)重、很頻繁的FullGC，從下面日志可以進(jìn)一步看出，這些FullGC都是在concurrentmodefailure模式下發(fā)生的，也就是虛擬機(jī)還未執(zhí)行完本次GC的情況下又來(lái)了大量數(shù)據(jù)導(dǎo)致JVM內(nèi)存不夠，此時(shí)虛擬機(jī)會(huì)將所有用戶線程掛起，執(zhí)行長(zhǎng)時(shí)間的FullGC！(concurrentmodefailure):45876255K->21800674K(46137344K),10.0625300secs]48792749K->21800674K(49283072K),[CMSPerm:43274K->43274K(262144K)],10.2083040secs][Times:user=12.02sys=0.00,real=10.20secs]2016-04-1421:22:43,990WARN[JvmPauseMonitor]util.JvmPauseMonitor:DetectedpauseinJVMorhostmachine(egGC):pauseofapproximately10055msGCpool'ParNew'hadcollection(s):count=2time=244msGCpool'ConcurrentMarkSweep'hadcollection(s):count=1time=10062ms上文提到FullGC會(huì)對(duì)上層業(yè)務(wù)產(chǎn)生很嚴(yán)重的影響，那有沒(méi)有可能會(huì)對(duì)下層依賴方也產(chǎn)生很大的影響呢？事實(shí)是Yes！而且，RS宕機(jī)的大部分原因也要?dú)w咎于此！進(jìn)一步查看日志，發(fā)現(xiàn)HBase日志中出現(xiàn)下述異常：2016-04-1421:22:44,006WARN[ResponseProcessorforblockBP-632656502-3-1448595094942:blk_1073941840_201226]hdfs.DFSClient:DFSOutputStreamResponseProcessorexceptionforblockBP-632656502-3-1448595094942:blk_1073941840_201226java.io.IOException:BadresponseERRORforblockBP-632656502-3-1448595094942:blk_1073941840_201226fromdatanode3:50010atorg.apache.hadoop.hdfs.DFSOutputStream$DataStreamer$ResponseProcessor.run(DFSOutputStream.java:732)從日志內(nèi)容來(lái)看應(yīng)該是hbase調(diào)用DFSClient從datanode加載block數(shù)據(jù)”BP-632656502-3-1448595094942:blk_1073941840_201226″，但是datanode返回失敗。具體失敗原因需要查看datanode節(jié)點(diǎn)日志，如下所示：2016-04-1421:22:43,789INFOorg.apache.hadoop.hdfs.server.datanode.DataNode:opWriteBlockBP-632656502-3-1448595094942:blk_1073941840_201226receivedexception.SocketTimeoutException:10000millistimeoutwhilewaitingforchanneltobereadyforread.ch:java.nio.channels.SocketChannel[connectedlocal=/4:50010remote=/4:30110]2016-04-1421:22:43,779ERRORorg.apache.hadoop.hdfs.server.datanode.DataNode::50010:DataXceivererrorprocessingWRITE_BLOCKoperationsrc:/4:30123dest:/4:50010.SocketTimeoutException:10000millistimeoutwhilewaitingforchanneltobereadyforread.ch:java.nio.channels.SocketChannel[connectedlocal=/4:50010remote=/4:30123]很顯然，從日志可以看出，datanode一直在等待來(lái)自客戶端的read請(qǐng)求，但是直至SocketTimeout，請(qǐng)求都沒(méi)有過(guò)來(lái)，此時(shí)datanode會(huì)將該連接斷開(kāi)，導(dǎo)致客戶端收到上述”BadresponseERROR***”的異常。那這和FullGC有什么關(guān)系呢？很簡(jiǎn)單，就是因?yàn)镕ullGC導(dǎo)致HBase所有內(nèi)部線程掛起，因此發(fā)往datanode的read請(qǐng)求也被掛起了，datanode就等啊等，左等右等都等不到，萬(wàn)不得已才將連接斷掉。查看Hadoop客戶端源碼可知，如果DFSClient發(fā)生上述異常，DFSClient會(huì)將一個(gè)全局標(biāo)志errorIndex設(shè)為一個(gè)非零值。具體可參見(jiàn)DFSOutputStream類中如下代碼片段：破案結(jié)局篇上述鋪墊篇最后的結(jié)果就是Hadoop客戶端會(huì)將一個(gè)全局標(biāo)志errorIndex設(shè)為一個(gè)非零值，那這到底和最終RS宕掉有什么關(guān)系呢？來(lái)繼續(xù)往下看。下圖HBase日志相關(guān)片段截圖，記錄了比較詳細(xì)的RS宕機(jī)異常信息，我們就以這些異常信息作為切入點(diǎn)進(jìn)行分析，可以看出至少三條有用的線索，如下圖所示：線索一：RS宕機(jī)最直接的原因是因?yàn)橄到y(tǒng)在關(guān)閉LogWriter（之后會(huì)重新開(kāi)啟一個(gè)新的HLog）的時(shí)候失敗線索二：執(zhí)行LogWriter關(guān)閉失敗的原因是”writingtrailer”時(shí)發(fā)生IOException異常線索三：而發(fā)生IOException異常的原因是”Alldatanodes***arebad”到這里為止，我們能夠獲得的最靠譜的情報(bào)就是RS宕機(jī)本質(zhì)是因?yàn)椤盇lldatanodes***arebad”造成的，看字面意思就是這臺(tái)datanode因?yàn)槟撤N原因壞掉了，那我們趕緊去看看datanode的日志，看看那個(gè)時(shí)間段有沒(méi)有相關(guān)的異?；蛘咤e(cuò)誤日志。然而很遺憾，datanode日志在那個(gè)時(shí)間點(diǎn)沒(méi)有打印任何異?；蛘咤e(cuò)誤日志，而且顯示所有服務(wù)都正常，信息如下所示：2016-04-1421:32:38,893INFOorg.apache.hadoop.hdfs.server.datanode.DataNode.clienttrace:src:,dest:,op:REQUEST_SHORT_CIRCUIT_FDS,blockid:1073941669,srvID:DS-22834907-4-50010-1448595406972,success:true2016-04-1421:32:38,894INFOorg.apache.hadoop.hdfs.server.datanode.DataNode.clienttrace:src:,dest:,op:REQUEST_SHORT_CIRCUIT_FDS,blockid:1073941669,srvID:DS-22834907-4-50010-1448595406972,success:true...看到這里，是不是有點(diǎn)蒙圈：HBase日志里面明明打印說(shuō)這臺(tái)datanode壞掉了，但是實(shí)際datanode日志顯示服務(wù)一切正常。這個(gè)時(shí)候就得翻翻源碼了，看看HBase在哪里打印的”Alld