解決HBase Replication在數據大量寫入時致使RegionServer崩潰問題

HBase在0.90以後的版本提供Replication功能，這些天本人在測試這個功能時發如今大量數據(>100W)寫入時會出現RegionServer崩潰的狀況。異常日誌以下：

2014-10-29 10:40:44,225 WARN org.apache.hadoop.hdfs.DFSClient: DFSOutputStream ResponseProcessor exception  for block blk_-2223802775658985697_1410java.io.EOFException
	at java.io.DataInputStream.readFully(DataInputStream.java:180)
	at java.io.DataInputStream.readLong(DataInputStream.java:399)
	at org.apache.hadoop.hdfs.protocol.DataTransferProtocol$PipelineAck.readFields(DataTransferProtocol.java:124)
	at org.apache.hadoop.hdfs.DFSClient$DFSOutputStream$ResponseProcessor.run(DFSClient.java:2967)

2014-10-29 10:40:44,225 INFO org.apache.hadoop.hdfs.DFSClient: Could not obtain block blk_-2223802775658985697_1410 from any node: java.io.IOException: No live nodes contain current block. Will get new block locations from namenode and retry...
2014-10-29 10:40:44,228 WARN org.apache.hadoop.hdfs.DFSClient: Error Recovery for block blk_-2223802775658985697_1410 bad datanode[0] 192.168.11.55:40010
2014-10-29 10:40:44,232 WARN org.apache.hadoop.hdfs.DFSClient: Error while syncing
java.io.IOException: All datanodes 192.168.11.55:40010 are bad. Aborting...
	at org.apache.hadoop.hdfs.DFSClient$DFSOutputStream.processDatanodeError(DFSClient.java:3096)
	at org.apache.hadoop.hdfs.DFSClient$DFSOutputStream.access$2100(DFSClient.java:2589)
	at org.apache.hadoop.hdfs.DFSClient$DFSOutputStream$DataStreamer.run(DFSClient.java:2793)
2014-10-29 10:40:44,235 FATAL org.apache.hadoop.hbase.regionserver.wal.HLog: Could not sync. Requesting close of hlog
java.io.IOException: Reflection
	at org.apache.hadoop.hbase.regionserver.wal.SequenceFileLogWriter.sync(SequenceFileLogWriter.java:310)
	at org.apache.hadoop.hbase.regionserver.wal.HLog.syncer(HLog.java:1366)
	at org.apache.hadoop.hbase.regionserver.wal.HLog.sync(HLog.java:1476)
	at org.apache.hadoop.hbase.regionserver.HRegion.syncOrDefer(HRegion.java:5970)
	at org.apache.hadoop.hbase.regionserver.HRegion.doMiniBatchMutation(HRegion.java:2490)
	at org.apache.hadoop.hbase.regionserver.HRegion.batchMutate(HRegion.java:2190)
	at org.apache.hadoop.hbase.regionserver.HRegionServer.multi(HRegionServer.java:3888)
	at sun.reflect.GeneratedMethodAccessor33.invoke(Unknown Source)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
	at java.lang.reflect.Method.invoke(Method.java:597)
	at org.apache.hadoop.hbase.ipc.WritableRpcEngine$Server.call(WritableRpcEngine.java:323)
	at org.apache.hadoop.hbase.ipc.HBaseServer$Handler.run(HBaseServer.java:1434)
Caused by: java.lang.reflect.InvocationTargetException
	at sun.reflect.GeneratedMethodAccessor35.invoke(Unknown Source)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
	at java.lang.reflect.Method.invoke(Method.java:597)
	at org.apache.hadoop.hbase.regionserver.wal.SequenceFileLogWriter.sync(SequenceFileLogWriter.java:308)
	... 11 more
Caused by: java.io.IOException: DFSOutputStream is closed
	at org.apache.hadoop.hdfs.DFSClient$DFSOutputStream.sync(DFSClient.java:3669)
	at org.apache.hadoop.fs.FSDataOutputStream.sync(FSDataOutputStream.java:97)
	at org.apache.hadoop.io.SequenceFile$Writer.syncFs(SequenceFile.java:995)
	... 15 more

實際上，這個問題並非由Replication功能引發的，而由客戶端在數據密集寫入時超時引發的

============================如下內容來源於網絡===================================

正常狀況下DFSClient寫block數據的過程是：

1. DFSClient端
   a）DFSOutputStream負責數據的接收和寫入，即經過DFSOutputSummer中的write方法（synchronized）得到數據，而sync（主要代碼 synchronized(this)）經過FlushBuffer創建packet後，經過enqueuePacket向dataQueue中寫入數據。
   b）DFSOutputStream中的DataStreamer（Daemon線程），負責向DataNode發送數據，每次發送前會檢查dataQueue中是否有數據，沒有就等待。
   c）DataStreamer創建pipeline傳輸數據時，對這個pipeline會起一個ResponseProcessor（Thread）去得到DataNode的反饋ack，並判斷是否有錯誤、進行recoverBlock等
2. DataNode端
   a）在每一個packet傳輸過程當中，根據創建數據傳輸的pipleLine，上游依次向下遊發送數據，下游依次向上遊發送ack。
   b）pipeline的最後一個節點（numTarget=0），PacketResponder 會一直運行lastDatanodeRun?方法，這個方法會在ack發送完畢(ackQueue.size()=0)後約1/2個dfs.socket.timeout?時刻發送心跳包，沿着pipeline發送給client。
3. HBase端
  HBase端經過hlog中的writer向hdfs寫數據，每次有數據寫入，都會sync。同時，HLog中有個logSyncer，默認配置是每秒鐘調用一次sync，無論有沒有數據寫入。


這個問題首先是因爲超時引發的，咱們先分析一下超時先後DFSClient和DataNode上發生了什麼。
1. 問題重現
    a）客戶端ResponseProcessor報69秒socket超時，出錯點在PipelineAck.readFields()。出錯後直接catch，標記hasError=true，closed=true。這個線程不會中止。
    b）DataStreamer在輪詢中調用processDatanodeError對hasError=true進行處理。此時errorIndex=0（默認值），首先會拋出Recovery for Block的異常. 而後關閉blockstream，從新基於兩個節點的pipeline進行recoverBlock。
    c）在DataNode上，processDatanodeError()關閉blockstream。這將致使pipeline中的packetResponder被interrupted和terminated。
    d）在DataNode上，processDatanodeError()關閉blockstream，致使BlockReceiver的readNextPacket()中的readToBuf讀取不到數據，throw EOFException的異常。這個異常一直向上拋，直到DataXceiver的run中，它將致使DataXceiver停止運行，提示DataNode.dnRegistration Error。
   e）recoverBlock會正常進行，並先在兩個節點上完成（第二個和第三個）。隨後Namenode會發現replicas數量不足，向DataNode發起transfer block的命令，這是一個異步的過程。可是在hlog檢查時，transfer頗有可能未完成，這時會報 pipeline error detected. Found 2 replicas but expecting 3 replicas。並關閉hlog。


以上就是根據日誌能夠看到的錯誤過程。
2. 問題分析
a)爲何會超時，爲何心跳包沒有發？
根據以上的分析，ResponseProcessor socket 69秒超時是致使後續一系列異常和hlog關閉的緣由。那麼爲什麼會發生socket超時？ResponseProcessor應該會在dfs.socket.timeout的1/2時間內收到HeartBeat包。
通過打印日誌，咱們發現，DataNode上配置的dfs.socket.timeout爲180秒，而HBase調用DFSClient時採用默認配置，即60秒。所以，DFSClient認爲超時時間爲3×nodes.length+60=69秒，而DataNode端發送心跳包的timeout=1/2×180=90秒！所以，若是在沒有數據寫入的狀況下，DataNode將在90秒後發送心跳包，此時DFSClient已經socketTimeout了，並致使後續的一系列現象。
b）爲何會在69秒內沒有新的packet發送過去呢？
咱們先分析一下DFSOutputStream寫數據和sync的同步關係。DFSOutputStream繼承自FSOutputSummer，DFSOutputStream接收數據是經過FSOutputSummer的write方法，這個方法是synchronized。而sync方法的flushBuffer()和enqueuePacket()，也在synchronized(this)代碼塊中。也就是說，對一個DFSOutputStream線程，若是sync和write同時調用，將發生同步等待。在HBase的場景下，sync發生的頻率很是高，sync搶到鎖的可能性很大。這樣，就頗有可能在不斷的sync，不斷的flushBuffer，可是卻沒能經過write寫入數據（被blocked了）。這就是致使超時時間內一直沒有packet發送的緣由。

綜上，HBase業務調用的特色和DFSOutputStream的synchronized代碼塊，頗有可能69秒中沒有packet寫入。但這個時候，不該該socket超時，socket超時是這個問題的根本緣由，而socket超時的緣由是配置不一致。


3. 問題解決

在hdfs端和HBase端，給dfs.socket.timeout設置一個較大的值，好比300000（300秒）【注意兩處設置的值要相等】