HBase問題診斷 – RegionServer宕機(jī) – 有態(tài)度的HBase/Spark/BigData http://hbasefly.com/2016/04/15/hbase-regionserver-crash/
GC時(shí)間長最明顯的危害是會(huì)造成上層業(yè)務(wù)的阻塞，通過日志也可以看出些許端倪：
//
經(jīng)過對整個(gè)案件的整理分析嘴办，一方面再次鍛煉了如何通過監(jiān)控弹谁、日志以及源碼定位排查問題的功底乾巧，另一方面在HBase運(yùn)維過程中也需要特別關(guān)注如下幾點(diǎn)：
- Full GC不僅會(huì)嚴(yán)重影響上層業(yè)務(wù)，造成業(yè)務(wù)讀寫請求的卡頓预愤。另外還有可能造成與HDFS之間數(shù)據(jù)請求的各種異常沟于，這種異常嚴(yán)重的時(shí)候甚至?xí)?dǎo)致RegionServer宕機(jī)。
- 上文中提到Full GC基本是由于Concurrent Mode Failure造成植康，這種Full GC場景比較少見旷太，通常可以通過減小 JVM 參數(shù)XX:CMSInitiatingOccupancyFraction來避免销睁，這個(gè)參數(shù)用來設(shè)置CMS垃圾回收時(shí)機(jī)供璧，假如此時(shí)設(shè)置為60，表示JVM內(nèi)已使用內(nèi)存占到總內(nèi)存的60%的時(shí)候就會(huì)進(jìn)行垃圾回收冻记，減少該值可以使得垃圾回收更早進(jìn)行睡毒。
- 一定要嚴(yán)格限制業(yè)務(wù)層面的流量。一方面需要和業(yè)務(wù)方交流冗栗，由業(yè)務(wù)方進(jìn)行限制演顾，另一方面可以探索HBase業(yè)務(wù)資源隔離的新方案供搀；
本來靜謐的晚上，吃著葡萄干看著球賽偶房，何等愜意趁曼【可偏偏一條報(bào)警短信如閃電一般打破了夜晚的寧靜棕洋，線上集群一臺(tái)RS宕了！于是倏地從床上坐起來乒融，看了看監(jiān)控掰盘，瞬間驚呆了：單臺(tái)機(jī)器的讀寫吞吐量竟然達(dá)到了5w ops/sec！RS宕機(jī)是因?yàn)檫@么大的寫入量造成的赞季？如果真是這樣愧捕，它是怎么造成的？如果不是這樣申钩，那又是什么原因次绘？各種疑問瞬間從腦子里一一閃過，甭管那么多撒遣，先把日志備份一份邮偎，再把RS拉起來。接下來還是Bug排查老套路：日志义黎、監(jiān)控和源碼三管齊下禾进，來看看到底發(fā)生了什么！
案件現(xiàn)場篇
下圖是使用監(jiān)控工具Ganglia對事發(fā)RegionServer當(dāng)時(shí)讀寫吞吐量的監(jiān)控曲線廉涕，從圖中可以看出泻云，大約在19點(diǎn)~21點(diǎn)半的時(shí)間段內(nèi)，這臺(tái)RS的吞吐量都維持了3w ops/sec左右狐蜕，峰值更是達(dá)到了6w ops/sec宠纯。之前我們就線上單臺(tái)RS能夠承受的最大讀寫吞吐量進(jìn)行過測定，基本也就維持在2w左右层释，主要是因?yàn)榫W(wǎng)絡(luò)帶寬瓶頸婆瓜。而在宕機(jī)前這臺(tái)RS的讀寫吞吐量超出這么多，直覺告訴我RS宕機(jī)原因就是它湃累！
接著就趕緊把日志拉出來看勃救，滿屏的responseTooSlow，如下圖所示：
很顯然治力，這種異常最大可能原因就是Full GC蒙秒，果然，經(jīng)過耐心地排查宵统，可以看到很多如下所示的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 20542msGC pool 'ParNew' had collection(s): count=1 time=0msGC pool 'ConcurrentMarkSweep' had collection(s): count=2 time=20898ms2016-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執(zhí)行了一次CMS GC覆获，導(dǎo)致整個(gè)進(jìn)程所有線程被掛起了20s。通過對MemStore的監(jiān)控也可以看出這段時(shí)間GC力度之大瓢省，如下圖所示：
GC時(shí)間長最明顯的危害是會(huì)造成上層業(yè)務(wù)的阻塞弄息，通過日志也可以看出些許端倪：
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 error2016-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服務(wù)端因?yàn)镕ull GC導(dǎo)致一直無法響應(yīng)用戶請求，用戶客戶端程序在一定時(shí)間過后就會(huì)SocketTimeout并斷掉此Connection勤婚。連接斷掉之后摹量，服務(wù)器端就會(huì)打印如上日志。然而馒胆，這些和我們的終極目標(biāo)好像并沒有太大關(guān)系缨称，別忘了我們的目標(biāo)是找到RS宕機(jī)的原因哦！
破案鋪墊篇
經(jīng)過對案件現(xiàn)場的排查祝迂，唯一有用的線索就是HBase在宕機(jī)前經(jīng)歷了很嚴(yán)重睦尽、很頻繁的Full GC，從下面日志可以進(jìn)一步看出型雳，這些Full GC都是在 concurrent mode failure模式下發(fā)生的当凡，也就是虛擬機(jī)還未執(zhí)行完本次GC的情況下又來了大量數(shù)據(jù)導(dǎo)致JVM內(nèi)存不夠，此時(shí)虛擬機(jī)會(huì)將所有用戶線程掛起纠俭，執(zhí)行長時(shí)間的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 10055msGC pool 'ParNew' had collection(s): count=2 time=244msGC pool 'ConcurrentMarkSweep' had collection(s): count=1 time=10062ms
上文提到Full GC會(huì)對上層業(yè)務(wù)產(chǎn)生很嚴(yán)重的影響，那有沒有可能會(huì)對下層依賴方也產(chǎn)生很大的影響呢柑晒？事實(shí)是Yes欧瘪！而且，RS宕機(jī)的大部分原因也要?dú)w咎于此匙赞！
進(jìn)一步查看日志佛掖，發(fā)現(xiàn)HBase日志中出現(xiàn)下述異常：
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:50010at org.apache.hadoop.hdfs.DFSOutputStream$DataStreamer$ResponseProcessor.run(DFSOutputStream.java:732)
從日志內(nèi)容來看應(yīng)該是hbase調(diào)用DFSClient從datanode加載block數(shù)據(jù)”BP-632656502-10.160.173.93-1448595094942:blk_1073941840_201226″，但是datanode返回失敗涌庭。具體失敗原因需要查看datanode節(jié)點(diǎn)日志芥被，如下所示：
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:50010java.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，請求都沒有過來席镀，此時(shí)datanode會(huì)將該連接斷開匹中，導(dǎo)致客戶端收到上述”Bad response ERROR ***”的異常。
那這和Full GC有什么關(guān)系呢豪诲？很簡單顶捷，就是因?yàn)镕ull GC導(dǎo)致HBase所有內(nèi)部線程掛起，因此發(fā)往datanode的read請求也被掛起了屎篱，datanode就等啊等服赎，左等右等都等不到葵蒂，萬不得已才將連接斷掉。
查看Hadoop客戶端源碼可知重虑，如果DFSClient發(fā)生上述異常践付，DFSClient會(huì)將一個(gè)全局標(biāo)志errorIndex設(shè)為一個(gè)非零值。具體可參見DFSOutputStream類中如下代碼片段：
破案結(jié)局篇
上述鋪墊篇最后的結(jié)果就是Hadoop客戶端會(huì)將一個(gè)全局標(biāo)志errorIndex設(shè)為一個(gè)非零值缺厉，那這到底和最終RS宕掉有什么關(guān)系呢永高？來繼續(xù)往下看。下圖HBase日志相關(guān)片段截圖芽死，記錄了比較詳細(xì)的RS宕機(jī)異常信息乏梁，我們就以這些異常信息作為切入點(diǎn)進(jìn)行分析，可以看出至少三條有用的線索关贵，如下圖所示：
線索一：RS宕機(jī)最直接的原因是因?yàn)橄到y(tǒng)在關(guān)閉LogWriter（之后會(huì)重新開啟一個(gè)新的HLog）的時(shí)候失敗
線索二：執(zhí)行LogWriter關(guān)閉失敗的原因是”writing trailer”時(shí)發(fā)生IOException異常
線索三：而發(fā)生IOException異常的原因是”All datanodes *** are bad”
到這里為止，我們能夠獲得的最靠譜的情報(bào)就是RS宕機(jī)本質(zhì)是因?yàn)椤盇ll datanodes *** are bad”造成的卖毁，看字面意思就是這臺(tái)datanode因?yàn)槟撤N原因壞掉了揖曾，那我們趕緊去看看datanode的日志，看看那個(gè)時(shí)間段有沒有相關(guān)的異澈ダ玻或者錯(cuò)誤日志炭剪。
然而很遺憾，datanode日志在那個(gè)時(shí)間點(diǎn)沒有打印任何異诚柰眩或者錯(cuò)誤日志奴拦，而且顯示所有服務(wù)都正常，信息如下所示：
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: true2016-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...
看到這里届吁，是不是有點(diǎn)蒙圈：HBase日志里面明明打印說這臺(tái)datanode壞掉了错妖，但是實(shí)際datanode日志顯示服務(wù)一切正常。這個(gè)時(shí)候就得翻翻源碼了疚沐，看看HBase在哪里打印的”All datanodes *** are bad“暂氯，通過查看源碼，可以看出最終元兇就是上文提到的errorIndex亮蛔，如下圖所示：
終于撥開天日了痴施，再不完結(jié)就要暈了！上文鋪墊篇鋪墊到最后就得出來因?yàn)镕ull GC最終導(dǎo)致DFSClient將一個(gè)全局標(biāo)志errorIndex設(shè)為一個(gè)非零值究流，在這里終于碰頭了辣吃，簡直淚流滿面！
案件梳理篇
整個(gè)流程走下來本人都有點(diǎn)暈暈的芬探，涉及的方方面面太多神得，因此有必要把整個(gè)流程完整的梳理一遍，下面簡單畫了一個(gè)示意圖：
經(jīng)過對整個(gè)案件的整理分析灯节，一方面再次鍛煉了如何通過監(jiān)控循头、日志以及源碼定位排查問題的功底绵估，另一方面在HBase運(yùn)維過程中也需要特別關(guān)注如下幾點(diǎn)：
Full GC不僅會(huì)嚴(yán)重影響上層業(yè)務(wù)，造成業(yè)務(wù)讀寫請求的卡頓卡骂。另外還有可能造成與HDFS之間數(shù)據(jù)請求的各種異常国裳，這種異常嚴(yán)重的時(shí)候甚至?xí)?dǎo)致RegionServer宕機(jī)。
上文中提到Full GC基本是由于Concurrent Mode Failure造成全跨，這種Full GC場景比較少見缝左，通常可以通過減小 JVM 參數(shù)XX:CMSInitiatingOccupancyFraction來避免浓若，這個(gè)參數(shù)用來設(shè)置CMS垃圾回收時(shí)機(jī)渺杉，假如此時(shí)設(shè)置為60，表示JVM內(nèi)已使用內(nèi)存占到總內(nèi)存的60%的時(shí)候就會(huì)進(jìn)行垃圾回收挪钓，減少該值可以使得垃圾回收更早進(jìn)行是越。
一定要嚴(yán)格限制業(yè)務(wù)層面的流量。一方面需要和業(yè)務(wù)方交流碌上，由業(yè)務(wù)方進(jìn)行限制倚评，另一方面可以探索HBase業(yè)務(wù)資源隔離的新方案；
