HBase Full GC宕機(jī)

最近在給HBase集群進(jìn)行擴(kuò)容，然而事事不順：

1.新添加的機(jī)器中有一臺(tái)竟然無故重啟，這個(gè)問題直接推給了系統(tǒng)部。

2.部署完HDFS和HBase后，啟動(dòng)都沒有任何問題，然而過一夜后，HBase節(jié)點(diǎn)全部宕掉。

更奇怪的是，以前老集群中的節(jié)點(diǎn)沒有問題，運(yùn)行正常，只有新添加的幾個(gè)節(jié)點(diǎn)宕掉，而且HDFS運(yùn)行也正常（除了機(jī)器重啟的那個(gè)節(jié)點(diǎn)）。

于是各種查看日志。

HBase日志顯示如下：JVM暫停時(shí)間過長(zhǎng)，導(dǎo)致無法與zookeeper通信，被zookeeper認(rèn)為該節(jié)點(diǎn)已經(jīng)宕掉，于是就關(guān)閉了該節(jié)點(diǎn)。

是不是真的發(fā)生了Full GC? 為什么會(huì)發(fā)生GC，暫停應(yīng)用呢？老集群中的機(jī)器為什么沒問題呢？由于對(duì)GC理解太淺，于是產(chǎn)生了各種問題，網(wǎng)上也沒查到具體答案，只能一點(diǎn)一點(diǎn)查詢、理解、梳理。

2015-10-13 23:47:12,295 WARN  [JvmPauseMonitor] util.JvmPauseMonitor: Detected pause in JVM or host machine (eg GC): pause of approximately 83095ms
GC pool 'ParNew' had collection(s): count=2 time=216ms
GC pool 'ConcurrentMarkSweep' had collection(s): count=2 time=330ms
2015-10-13 23:47:12,295 WARN  [regionserver60020] util.Sleeper: We slept 85995ms 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
2015-10-13 23:47:12,295 INFO  [regionserver60020-SendThread(zookeeper2:2181)] zookeeper.ClientCnxn: Client session timed out, have not heard from server in 95659ms for sessionid 0x25053f6801406ac, closing socket connection and attempting reconnect
2015-10-13 23:47:12,291 WARN  [regionserver60020.compactionChecker] util.Sleeper: We slept 89894ms instead of 10000ms, 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
2015-10-13 23:47:12,291 WARN  [regionserver60020.periodicFlusher] util.Sleeper: We slept 89894ms instead of 10000ms, 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
2015-10-13 23:47:12,291 INFO  [regionserver60020-SendThread(zookeeper3:2181)] zookeeper.ClientCnxn: Client session timed out, have not heard from server in 89644ms for sessionid 0x1505ebc2da3010f, closing socket connection and attempting reconnect
2015-10-13 23:47:12,397 FATAL [regionserver60020] regionserver.HRegionServer: ABORTING region server hregion151,60020,1444732375821: org.apache.hadoop.hbase.YouAreDeadException: Server REPORT rejected; currently processing hregion151,60020,1444732375821 as dead server

在HBase的安裝目錄下有個(gè)gclog.0文件，記錄了HBase運(yùn)行時(shí)發(fā)生的垃圾回收信息。

但是各種查看后，也沒發(fā)現(xiàn)什么問題。（或許是對(duì)GC不懂的緣故吧，不懂就查、學(xué)唄）。

2015-10-13T18:35:47.314+0800: 165.893: [GC [1 CMS-initial-mark: 32523K(63872K)] 35370K(83008K), 0.0185230 secs] [Times: user=0.01 sys=0.02, real=0.01 secs] 
2015-10-13T18:35:47.333+0800: 165.912: [CMS-concurrent-mark-start]
2015-10-13T18:35:47.402+0800: 165.981: [CMS-concurrent-mark: 0.046/0.069 secs] [Times: user=0.32 sys=0.03, real=0.07 secs] 
2015-10-13T18:35:47.402+0800: 165.982: [CMS-concurrent-preclean-start]
2015-10-13T18:35:47.411+0800: 165.990: [CMS-concurrent-preclean: 0.008/0.009 secs] [Times: user=0.02 sys=0.00, real=0.01 secs] 
2015-10-13T18:35:47.411+0800: 165.990: [CMS-concurrent-abortable-preclean-start]
2015-10-13T18:35:47.414+0800: 165.993: [GC 165.993: [ParNew: 18503K->2112K(19136K), 0.0681050 secs] 51027K->37708K(83008K), 0.0682600 secs] [Times: user=0.03 sys=0.07, real=0.06 secs] 
2015-10-13T18:35:47.535+0800: 166.115: [CMS-concurrent-abortable-preclean: 0.028/0.124 secs] [Times: user=0.15 sys=0.09, real=0.13 secs] 
2015-10-13T18:35:47.536+0800: 166.115: [GC[YG occupancy: 14168 K (19136 K)]166.115: [Rescan (parallel) , 0.0024340 secs]166.117: [weak refs processing, 0.0001320 secs] [1 CMS-remark: 35596K(63872K)] 49765K(83008K), 0.0026970 secs] [Times: user=0.03 sys=0.00, real=0.00 secs] 
2015-10-13T18:35:47.539+0800: 166.118: [CMS-concurrent-sweep-start]
2015-10-13T18:35:47.554+0800: 166.133: [CMS-concurrent-sweep: 0.014/0.015 secs] [Times: user=0.05 sys=0.01, real=0.02 secs] 
2015-10-13T18:35:47.554+0800: 166.133: [CMS-concurrent-reset-start]
2015-10-13T18:35:47.571+0800: 166.151: [GC 166.151: [ParNew: 19077K->2112K(19136K), 0.0028640 secs] 39044K->25755K(83008K), 0.0029990 secs] [Times: user=0.03 sys=0.00, real=0.01 secs]

在查詢和學(xué)習(xí)JVM的垃圾回收時(shí)，看到了下面這句話：

對(duì)于采用CMS進(jìn)行舊生代GC的程序而言，尤其要注意GC日志中是否有promotion failed和concurrent mode failure兩種狀況，當(dāng)這兩種狀況出現(xiàn)時(shí)可能會(huì)觸發(fā)Full GC。promotion failed是在進(jìn)行Minor GC時(shí)，survivor space放不下、對(duì)象只能放入舊生代，而此時(shí)舊生代也放不下造成的；

然而在HBase的gclog.0的日志文件結(jié)尾發(fā)現(xiàn)了promotion failed，日志如下。

2015-10-14T00:55:40.417+0800: 22958.996: [GC 22958.996: [ParNew (promotion failed): 19133K->19116K(19136K), 0.0752040 secs]22959.071: [CMS: 24832559K->11737235K(28395128K), 54.6409350 secs] 24849259K->11737235K(28414264K), [CMS Perm : 48374K->48253K(80800K)], 54.7223900 secs] [Times: user=7.80 sys=1.13, real=54.72 secs] 
2015-10-14T00:56:41.108+0800: 23019.687: [GC 23019.687: [ParNew: 221568K->9684K(249216K), 0.0259720 secs] 11958803K->11746920K(28644352K), 0.0261620 secs] [Times: user=0.29 sys=0.02, real=0.02 secs] 
Heap
 par new generation   total 249216K, used 128841K [0x0000000124e00000, 0x0000000135c60000, 0x0000000135c60000)
  eden space 221568K,  53% used [0x0000000124e00000, 0x000000012c25d198, 0x0000000132660000)
  from space 27648K,  35% used [0x0000000134160000, 0x0000000134ad53b0, 0x0000000135c60000)
  to   space 27648K,   0% used [0x0000000132660000, 0x0000000132660000, 0x0000000134160000)
 concurrent mark-sweep generation total 28395136K, used 11737235K [0x0000000135c60000, 0x00000007fae00000, 0x00000007fae00000)
 concurrent-mark-sweep perm gen total 80800K, used 48566K [0x00000007fae00000, 0x00000007ffce8000, 0x0000000800000000)