記一次 hadoop does not have enough number of replicas問題處理
背景 凌晨hadoop任務大量出現 does not have enough number of replicas
叢集版本 cdh5.13.3 hadoop2.6.0
首先百度 大部分人建議 dfs.client.block.write.locateFollowingBlock.retries = 10 大部分人給出的意見是因為cpu不足，具體都是copy別人的,因為我們的namenodecpu才用3%,所以我猜測他們的意思是客戶端cpu跑完了(我們的哭護短cpu用的還真的高)。 網上文章的意思是客戶端cpu不足導致客戶端上報到namenode有延時，超過了namenode的等待時間時間，所以報錯。 因為我們是生成環境，所以等待晚上重啟看效果。
第二天凌晨被電話吵醒，發現還是有很多同樣的報錯
這次不再盲目相信網上了，直接看日誌(實際上花了差不多四天 包括向售後提case)
第一步 namenode 日誌
2021-09-28 15:31:18,008 INFO org.apache.hadoop.hdfs.StateChange: BLOCK* allocateBlock: /user/hive/warehouse/stg.db/stg_erp_sal_bgy_order_head/part_date=20210928__ffbd3cf3_670b_4897_a885_5e8b1382f8dc/stg_erp_sal_bgy_order_head_data__5e6d17b5_98e0_471c_b58e_8a878bbfbf99. BP-1938937130-10.8.22.2-1516416995387 blk_2136776575_1063083777{blockUCState=UNDER_CONSTRUCTION, primaryNodeIndex=-1, replicas=[ReplicaUnderConstruction[[DISK]DS-2fb03e6c-cf60-4b12-8fcd-7cc92510c8ca:NORMAL:10.8.22.17:1004|RBW], ReplicaUnderConstruction[[DISK]DS-06c4c8c3-68ad-4089-b263-28364e71316b:NORMAL:10.8.56.9:1004|RBW], ReplicaUnderConstruction[[DISK]DS-363d48bc-7453-40e6-9977-25cec11aa18b:NORMAL:10.8.22.46:1004|RBW]]}
以上詳解
BLOCK* allocateBlock: 表示在申請block
BP-1938937130-10.8.22.2-1516416995387 這個是namenode的唯一標識 寫在VERSION裡面
/data/dfs/nn/current/VERSION
blk_2136776575_1063083777這個表示這個塊的名稱
UNDER_CONSTRUCTION：資料塊處於構建階段狀態下。它最近被分配，用於write或appendUNDER_CONSTRUCTION狀態下，檔案剛剛被create，或者正在被append，此時的資料塊正在被持續的寫入，其大小和時間戳都是可以更改的，但是這種狀態的下的資料塊對於讀是可見的，具體能讀多少則是由客戶端詢問DataNode得知的，該block的所有副本replica接收到的資料大小都會大於等於這個可讀的資料大小，這樣，才能保證所有的副本replica均可用
從上面可以看出資料的寫入順序
10.8.22.17 ----->10.8.56.9----> 10.8.22.46
第二步 找到日誌裡面的第一臺機器10.8.22.17 可以看到日誌
2021-09-28 15:31:18,013 INFO org.apache.hadoop.hdfs.server.datanode.DataNode: Receiving BP-1938937130-10.8.22.2-1516416995387:blk_2136776575_1063083777 src: /10.8.22.17:48703dest: /10.8.22.17:1004
2021-09-28 15:31:19,285 INFO org.apache.hadoop.hdfs.server.datanode.DataNode.clienttrace: src: /10.8.22.17:48703, dest: /10.8.22.17:1004, bytes: 62851, op: HDFS_WRITE, cliID:DFSClient_NONMAPREDUCE_-424249781_105, offset: 0, srvID: 2efdedb9-c953-46f7-b70b-7dfc402e138d, blockid: BP-1938937130-10.8.22.2-1516416995387:blk_2136776575_1063083777, duration: 377335230
2021-09-28 15:31:19,285 INFO org.apache.hadoop.hdfs.server.datanode.DataNode: PacketResponder: BP-1938937130-10.8.22.2-1516416995387:blk_2136776575_1063083777, type=HAS_DOWNSTREAM_IN_PIPELINE terminating
以上詳解
src: /10.8.22.17:48703, dest: /10.8.22.17:1004
表示客戶端是22.17 目標端也是22.17(namenode 選定的)
type=HAS_DOWNSTREAM_IN_PIPELINE terminating
這裡表示這個塊資料寫入完成 繼續寫入下一臺機器（資料寫入是序列的A-->B--->C）
10.8.56.9 日誌相同 不詳細寫
第三步 看10.8.22.46的日誌
2021-09-28 15:31:18,467 INFO org.apache.hadoop.hdfs.server.datanode.DataNode: Receiving BP-1938937130-10.8.22.2-1516416995387:blk_2136776575_1063083777 src: /10.8.56.9:57488 dest: /10.8.22.46:1004
2021-09-28 15:31:18,798 INFO org.apache.hadoop.hdfs.server.datanode.DataNode.clienttrace: src: /10.8.56.9:57488, dest: /10.8.22.46:1004, bytes: 62851, op: HDFS_WRITE, cliID: DFSClient_NONMAPREDUCE_-424249781_105, offset: 0, srvID: eefc5ad9-3e92-4640-99a9-7c4c5a4a27de, blockid: BP-1938937130-10.8.22.2-1516416995387:blk_2136776575_1063083777, duration: 14511253
2021-09-28 15:31:18,798 INFO org.apache.hadoop.hdfs.server.datanode.DataNode: PacketResponder: BP-1938937130-10.8.22.2-1516416995387:blk_2136776575_1063083777, type=LAST_IN_PIPELINE, downstreams=0:[] terminating
這裡沒什麼不同 只有type=LAST_IN_PIPELINE 表示這是最後一個塊兒了，他完成就可以向NAMENODE彙報寫入完成了
第四步 繼續看10.8.22.46的日誌
2021-09-28 15:31:52,723 INFO org.apache.hadoop.hdfs.server.datanode.fsdataset.impl.FsDatasetAsyncDiskService: Scheduling blk_2136776575_1063083777 file /data2/dfs/dn/current/BP-1938937130-10.8.22.2-1516416995387/current/finalized/subdir92/subdir159/blk_2136776575 for deletion
2021-09-28 15:31:52,740 INFO org.apache.hadoop.hdfs.server.datanode.fsdataset.impl.FsDatasetAsyncDiskService: Deleted BP-1938937130-10.8.22.2-1516416995387 blk_2136775295_1063082497 file /data1/dfs/dn/current/BP-1938937130-10.8.22.2-1516416995387/current/finalized/subdir92/subdir154/blk_2136775295
2021-09-28 15:31:52,740 INFO org.apache.hadoop.hdfs.server.datanode.fsdataset.impl.FsDatasetAsyncDiskService: Deleted BP-1938937130-10.8.22.2-1516416995387 blk_2136776575_1063083777 file /data2/dfs/dn/current/BP-1938937130-10.8.22.2-1516416995387/current/finalized/subdir92/subdir159/blk_2136776575
發現在31:52 有日誌輸出刪除這個block,為什麼會有這個操作呢？我們看namenode日誌
第五步撥開面紗
2021-09-28 15:31:19,287 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem: BLOCK* checkFileProgress: blk_2136776575_1063083777{blockUCState=COMMITTED, primaryNodeIndex=-1, replicas=[ReplicaUnderConstruction[[DISK]DS-2fb03e6c-cf60-4b12-8fcd-7cc92510c8ca:NORMAL:10.8.22.17:1004|RBW], ReplicaUnderConstruction[[DISK]DS-06c4c8c3-68ad-4089-b263-28364e71316b:NORMAL:10.8.56.9:1004|RBW], ReplicaUnderConstruction[[DISK]DS-363d48bc-7453-40e6-9977-25cec11aa18b:NORMAL:10.8.22.46:1004|RBW]]} has not reached minimal replication1
。。。。。。。。。
2021-09-28 15:31:31,695 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem: BLOCK* checkFileProgress: blk_2136776575_1063083777{blockUCState=COMMITTED, primaryNodeIndex=-1, replicas=[ReplicaUnderConstruction[[DISK]DS-2fb03e6c-cf60-4b12-8fcd-7cc92510c8ca:NORMAL:10.8.22.17:1004|RBW], ReplicaUnderConstruction[[DISK]DS-06c4c8c3-68ad-4089-b263-28364e71316b:NORMAL:10.8.56.9:1004|RBW], ReplicaUnderConstruction[[DISK]DS-363d48bc-7453-40e6-9977-25cec11aa18b:NORMAL:10.8.22.46:1004|RBW]]} has not reached minimal replication1
。。。這裡省略了四條日誌，內容和上面一樣 時間不一樣
這裡列印了六條日誌 表示 15:31:19 ---> 15:31:31 這12S內 資料還沒有寫入完成 也就是namenode沒有收到datanode的完整報告
但是我們看最後寫入的datanode(10.8.22.46)的日誌
dest: /10.8.22.46:1004, bytes: 62851, op: HDFS_WRITE, cliID: DFSClient_NONMAPREDUCE_-424249781_105, offset: 0, srvID: eefc5ad9-3e92-4640-99a9-7c4c5a4a27de, blockid: BP-1938937130-10.8.22.2-1516416995387:blk_2136776575_1063083777, duration: 14511253
2021-09-28 15:31:18,798 INFO org.apache.hadoop.hdfs.server.datanode.DataNode: PacketResponder: BP-1938937130-10.8.22.2-1516416995387:blk_2136776575_1063083777, type=LAST_IN_PIPELINE, downstreams=0:[] terminating
我們發現15:31:18就已經完成寫入了 ，說明了這段時間內dn和nn通訊有問題，
具體是nn還是dn的問題呢？ 我們可以繼續看nn的日誌
第六步 問題初現
2021-09-28 15:31:31,843 INFO BlockStateChange: BLOCK* InvalidateBlocks: add blk_2136776575_1063083777 to 10.8.22.46:1004
因為已經超過了6次（可配置）沒收到dn的彙報，上面提示 要求dn刪除資料blk_2136776575_1063083777
2021-09-28 15:31:31,843 INFO BlockStateChange: BLOCK* InvalidateBlocks: add blk_2136776575_1063083777 to 10.8.22.46:1004
這裡提示正式要求10.8.22.46刪除資料塊有這麼多
繼續看日誌
2021-09-28 15:31:43,862 INFO BlockStateChange: BLOCK* InvalidateBlocks: add blk_2136776575_1063083777 to 10.8.56.9:1004
要求 10.8.56.9同樣刪除快
繼續 要求 22.17刪除快
2021-09-28 15:33:20,593 INFO BlockStateChange: BLOCK* InvalidateBlocks: add blk_2136776575_1063083777 to 10.8.22.17:1004
第七步
分析: 從這一大塊刪除的塊挑選了幾個塊兒 在nn中查詢，發現都是這段時間寫入的塊兒。。。無一例外都失敗了，裡面以22.17最多。
但是無法確認就是這臺的dn問題
大概率還是namenode問題導致這一時間段（2s內）的通訊出問題，同理我們用的解決辦法也是減小nn的壓力，最後效果不錯。
另外我們的版本是2.6.0 據說全是bug的版本 還有很多可能影響nn
可以參考一下部落格
其實問題到這兒能大概判斷出問題，但是知道我看到下面的部落格才更加確認
https://blog.csdn.net/lipeng_bigdata/article/details/51145368
修改的配置
優化
1 dfs.client.block.write.locateFollowingBlock.retries = 10
這個引數是說client等待的次數由6次變為10次。
Cloudera Manager -> HDFS -> Configuration -> Enter hdfs-site.xml in search bar, add dfs.client.block.write.locateFollowingBlock.retries = 10 in "HDFS Client Advanced Configuration Snippet (Safety Valve) for hdfs-site.xml"
注意這個引數是加在client的hdfs-site.xml裡。
2 dfs.blockreport.incremental.intervalMsec = 300 ##這個最重要
這個引數是說datanode不立即回送block report給namenode，而是等300毫秒，然後一次性回送300毫秒內所有block的變化，這樣可以極大減輕namenode的壓力。
3 Cloudera Manager -> HDFS -> Configuration -> Enter hdfs-site.xml in search bar, add dfs.blockreport.incremental.intervalMsec = 300 in "HDFS Service Advanced Configuration Snippet (Safety Valve) for hdfs-site.xml"
注意這次加在service level的hdfs-site.xml裡。
dfs.client.socket-timeout=300000
是否為資料盤的問題
之前我一段懷疑可能是某個磁碟有問題(22.17概率最高) 但是我統計了下資料
發現和磁碟沒大關係！！
之所以我每次排查問題的塊兒都會落在22.17 是因為開發同事的程式在這臺機器上，hadoop利用最優方案 資料會首先寫入到這臺機器上！
修改後的效果
**cat ./hadoop-cmf-hdfs-NAMENODE-master1.log.out | grep InvalidateBlocks | wc -l**
1261
[root@master1 tmp_file]# !3016
cat ./hadoop-cmf-hdfs-NAMENODE-master1.log.out.1 | grep InvalidateBlocks | wc -l
64258
少了60倍InvalidateBlocks 不能清零的原因大概率還是因為bug 提官方case了 看能不能有回覆，畢竟5.13已經停止維護了。