感谢张老师的回复,由于我们这个大表快照的时间是近期才明显增长的,所以还是感觉hbase集群存在问题。我这边儿重新整理了下这个问题发生的全过程,辛苦张老师再帮忙看一下,再次感谢。


1、hbase集群信息:
3台虚拟机器:
作为hbase master,hdfs namenode,journal node,failovercontroller
14台物理机器:配置96c,376G,SSD盘
作为hbase region server,hdfs datanode


hbase版本:2.1.9
hadoop版本:hadoop-3.0.0-cdh-6.2.0
表:sdhz_user_info_realtime
大小:9.5TB
1个family


2、最近的操作:
2023年1月:sdhz_user_info_realtime表,region数量1024
2023年2月:因为sdhz_user_info_realtime表有很多脏数据,所以采用scan region的形式,一个一个region删除无用的列
2023年2月底:发现sdhz_user_info_realtime表的region数量暴增到4000多个,然后手动merge过region,造成hbase 
meta 空洞的问题,之后就放弃了merge,目前已经达到4800个region了
2023年3月16日夜间:sdhz_user_info_realtime表做snapshot超时,超时时间5分钟
2023年3月17日:将snapshot超时时间改为15分钟
2023年3月19日:snapshot再次超时
2023年3月20日:将snapshot超时时间改为60分钟,目前观察每次snapshot时间,大约半小时左右


3、想得到解答的问题:
为什么snapshot需要这么久?
region的数量如何降下去?




4、在此期间对问题进行了跟踪排查,整理的信息如下:




在snapshot的过程中,时间花费在region的flush上,snapshot的校验上
在出现“Done waiting - online snapshot 
for”日志之前,一直在做flush操作,所有region大约花费总共20多分钟,每个region的flush的时间大约是10~20s,每次flush了几MB到几十MB的memstore,每个region
 server上大约340个region
在出现“Done waiting - online snapshot for”日志之后,开始对snapshot进行校验,移动等操作,花费了10分钟


regionserver中发现了DFSClient的日志
2023-03-29 16:24:55,395 INFO org.apache.hadoop.hdfs.DFSClient: Could not 
complete 
/hbase/.hbase-snapshot/.tmp/sdhz_user_info_realtime_1680076952828/region-manifest.603b4d8028af279648af4bfaa3889fd0
 retrying...




datanode中发现了日志:
增量块上报过程中,同一个块,要上报好几次,例如下面的日志,blk_1109695462_35954673这个块,怀疑dn向nn发送IBR的过程中,有失败然后进入pendingIBR重试的,想通过arthas检测IBR上报过程中putMissing的方法


2023-03-29 16:16:51,367 DEBUG 
org.apache.hadoop.hdfs.server.datanode.IncrementalBlockReportManager: call 
blockReceivedAndDeleted: 
[DatanodeStorage[DS-059fc182-f7cc-43bd-a0c3-2e1447f6650f,DISK,NORMAL][blk_1109695462_35954673,
 status: RECEIVING_BLOCK, delHint: null, blk_1109695456_35954667, status: 
RECEIVED_BLOCK, delHint: null], 
DatanodeStorage[DS-b7afb119-fef7-429d-bf95-c7df181b7785,DISK,NORMAL][blk_1109695459_35954670,
 status: RECEIVING_BLOCK, delHint: null]]
2023-03-29 16:16:51,367 DEBUG 
org.apache.hadoop.hdfs.server.datanode.IncrementalBlockReportManager: call 
blockReceivedAndDeleted: 
[DatanodeStorage[DS-059fc182-f7cc-43bd-a0c3-2e1447f6650f,DISK,NORMAL][blk_1109695462_35954673,
 status: RECEIVING_BLOCK, delHint: null, blk_1109695456_35954667, status: 
RECEIVED_BLOCK, delHint: null], 
DatanodeStorage[DS-b7afb119-fef7-429d-bf95-c7df181b7785,DISK,NORMAL][blk_1109695459_35954670,
 status: RECEIVING_BLOCK, delHint: null]]
2023-03-29 16:16:51,370 DEBUG 
org.apache.hadoop.hdfs.server.datanode.IncrementalBlockReportManager: call 
blockReceivedAndDeleted: 
[DatanodeStorage[DS-b7afb119-fef7-429d-bf95-c7df181b7785,DISK,NORMAL][blk_1109695452_35954663,
 status: RECEIVED_BLOCK, delHint: null]]
2023-03-29 16:16:51,372 DEBUG 
org.apache.hadoop.hdfs.server.datanode.IncrementalBlockReportManager: call 
blockReceivedAndDeleted: 
[DatanodeStorage[DS-b7afb119-fef7-429d-bf95-c7df181b7785,DISK,NORMAL][blk_1109695459_35954670,
 status: RECEIVED_BLOCK, delHint: null]]
2023-03-29 16:16:51,380 DEBUG 
org.apache.hadoop.hdfs.server.datanode.IncrementalBlockReportManager: call 
blockReceivedAndDeleted: 
[DatanodeStorage[DS-059fc182-f7cc-43bd-a0c3-2e1447f6650f,DISK,NORMAL][blk_1109695462_35954673,
 status: RECEIVED_BLOCK, delHint: null], 
DatanodeStorage[DS-b7afb119-fef7-429d-bf95-c7df181b7785,DISK,NORMAL][blk_1109695468_35954679,
 status: RECEIVING_BLOCK, delHint: null]]
2023-03-29 16:16:51,552 DEBUG 
org.apache.hadoop.hdfs.server.datanode.IncrementalBlockReportManager: call 
blockReceivedAndDeleted: 
[DatanodeStorage[DS-059fc182-f7cc-43bd-a0c3-2e1447f6650f,DISK,NORMAL][blk_1109695391_35954602,
 status: RECEIVED_BLOCK, delHint: null]]
2023-03-29 16:16:51,574 DEBUG 
org.apache.hadoop.hdfs.server.datanode.IncrementalBlockReportManager: call 
blockReceivedAndDeleted: 
[DatanodeStorage[DS-059fc182-f7cc-43bd-a0c3-2e1447f6650f,DISK,NORMAL][blk_1109695455_35954666,
 status: RECEIVED_BLOCK, delHint: null]]
2023-03-29 16:16:52,094 DEBUG 
org.apache.hadoop.hdfs.server.datanode.IncrementalBlockReportManager: call 
blockReceivedAndDeleted: 
[DatanodeStorage[DS-b7afb119-fef7-429d-bf95-c7df181b7785,DISK,NORMAL][blk_1109695468_35954679,
 status: RECEIVED_BLOCK, delHint: null]]
2023-03-29 16:16:53,164 DEBUG 
org.apache.hadoop.hdfs.server.datanode.IncrementalBlockReportManager: call 
blockReceivedAndDeleted: 
[DatanodeStorage[DS-b7afb119-fef7-429d-bf95-c7df181b7785,DISK,NORMAL][blk_1109695447_35954658,
 status: RECEIVED_BLOCK, delHint: null]]
2023-03-29 16:16:55,574 DEBUG 
org.apache.hadoop.hdfs.server.datanode.IncrementalBlockReportManager: call 
blockReceivedAndDeleted: 
[DatanodeStorage[DS-b7afb119-fef7-429d-bf95-c7df181b7785,DISK,NORMAL][blk_1109695351_35954562,
 status: RECEIVED_BLOCK, delHint: null]]
2023-03-29 16:16:56,894 DEBUG 
org.apache.hadoop.hdfs.server.datanode.IncrementalBlockReportManager: call 
blockReceivedAndDeleted: 
[DatanodeStorage[DS-059fc182-f7cc-43bd-a0c3-2e1447f6650f,DISK,NORMAL][blk_1109695391_35954602,
 status: RECEIVED_BLOCK, delHint: null, blk_1109695462_35954673, status: 
RECEIVED_BLOCK, delHint: null, blk_1109695455_35954666, status: RECEIVED_BLOCK, 
delHint: null], 
DatanodeStorage[DS-b7afb119-fef7-429d-bf95-c7df181b7785,DISK,NORMAL][blk_1109695351_35954562,
 status: RECEIVED_BLOCK, delHint: null, blk_1109695459_35954670, status: 
RECEIVED_BLOCK, delHint: null, blk_1109695468_35954679, status: RECEIVED_BLOCK, 
delHint: null, blk_1109695447_35954658, status: RECEIVED_BLOCK, delHint: null, 
blk_1109695452_35954663, status: RECEIVED_BLOCK, delHint: null]]




namenode中发现日志:


2023-03-29 16:24:54,995 INFO 
org.apache.hadoop.hdfs.server.namenode.FSNamesystem: BLOCK* 
blk_1109699571_35958782 is COMMITTED but not COMPLETE(numNodes= 0 <  minimum = 
1) in file 
/hbase/.hbase-snapshot/.tmp/sdhz_user_info_realtime_1680076952828/region-manifest.603b4d8028af279648af4bfaa3889fd0




2023-03-30 12:21:39,963 WARN 
org.apache.hadoop.hdfs.server.blockmanagement.BlockPlacementPolicy: Failed to 
place enough replicas, still in need of 3 to reach 3 (unavailableStorages=[], 
storagePolicy=BlockStoragePolicy{ALL_SSD:12, storageTypes=[SSD], 
creationFallbacks=[DISK], replicationFallbacks=[DISK]}, newBlock=true) For more 
information, please enable DEBUG log level on 
org.apache.hadoop.hdfs.server.blockmanagement.BlockPlacementPolicy and 
org.apache.hadoop.net.NetworkTopology




2023-03-30 12:22:53,300 WARN 
org.apache.hadoop.hdfs.server.blockmanagement.BlockPlacementPolicy: Failed to 
place enough replicas, still in need of 3 to reach 3 (unavailableStorages=[], 
storagePolicy=BlockStoragePolicy{ALL_SSD:12, storageTypes=[SSD], 
creationFallbacks=[DISK], replicationFallbacks=[DISK]}, newBlock=true)
2023-03-30 12:22:53,300 DEBUG org.apache.hadoop.net.NetworkTopology: Choosing 
random from 10 available nodes on node /, scope=, excludedScope=/TX/T10/10, 
excludeNodes=[x.x.x.x:9866]. numOfDatanodes=10.
2023-03-30 12:22:53,300 DEBUG org.apache.hadoop.net.NetworkTopology: Choosing 
random from 12 available nodes on node /, scope=, excludedScope=/TX/T01/02, 
excludeNodes=[x.x.x.x:9866]. numOfDatanodes=12.
2023-03-30 12:22:53,300 DEBUG org.apache.hadoop.net.NetworkTopology: 
nthValidToReturn is 5
2023-03-30 12:22:53,300 DEBUG org.apache.hadoop.net.NetworkTopology: 
nthValidToReturn is 5
2023-03-30 12:22:53,300 DEBUG org.apache.hadoop.net.NetworkTopology: Chosen 
node x.x.x.x:9866 from first random
2023-03-30 12:22:53,300 DEBUG org.apache.hadoop.net.NetworkTopology: 
chooseRandom returning x.x.x.x:9866
2023-03-30 12:22:53,300 DEBUG org.apache.hadoop.net.NetworkTopology: Chosen 
node x.x.x.x:9866 from first random
2023-03-30 12:22:53,300 DEBUG org.apache.hadoop.net.NetworkTopology: 
chooseRandom returning x.x.x.x:9866
2023-03-30 12:22:53,301 DEBUG org.apache.hadoop.net.NetworkTopology: Choosing 
random from 3 available nodes on node /TX/T01/04, scope=/TX/T01/04, 
excludedScope=null, excludeNodes=[x.x.x.x:9866, x.x.x.x:9866]. numOfDatanodes=4.
2023-03-30 12:22:53,301 DEBUG org.apache.hadoop.net.NetworkTopology: Choosing 
random from 0 available nodes on node /TX/T02/02, scope=/TX/T02/02, 
excludedScope=null, excludeNodes=[x.x.x.x:9866, x.x.x.x:9866]. numOfDatanodes=1.
2023-03-30 12:22:53,301 DEBUG org.apache.hadoop.net.NetworkTopology: 
nthValidToReturn is 0
2023-03-30 12:22:53,301 DEBUG org.apache.hadoop.net.NetworkTopology: Chosen 
node x.x.x.x:9866 from first random
2023-03-30 12:22:53,301 DEBUG org.apache.hadoop.net.NetworkTopology: 
chooseRandom returning x.x.x.x:9866
2023-03-30 12:22:53,301 DEBUG org.apache.hadoop.net.NetworkTopology: 
chooseRandom returning null
2023-03-30 12:22:53,301 DEBUG org.apache.hadoop.net.NetworkTopology: No node to 
choose.
2023-03-30 12:22:53,301 INFO org.apache.hadoop.hdfs.StateChange: BLOCK* 
allocate blk_1109782685_36041896, replicas=x.x.x.x:9866, x.x.x.x:9866, 
x.x.x.x:9866 for 
/hbase/WALs/hbase-virgo-rs-18.bigdata.bj.tx.lan,16020,1679431900739/hbase-virgo-rs-18.bigdata.bj.tx.lan%2C16020%2C1679431900739.hbase-virgo-rs-18.bigdata.bj.tx.lan%2C16020%2C1679431900739.regiongroup-0.1680150172590
2023-03-30 12:22:53,301 DEBUG 
org.apache.hadoop.hdfs.server.blockmanagement.BlockPlacementPolicy: Failed to 
choose from local rack (location = /TX/T02/02), retry with the rack of the next 
replica (location = /TX/T01/02)
org.apache.hadoop.hdfs.server.blockmanagement.BlockPlacementPolicy$NotEnoughReplicasException:
        at 
org.apache.hadoop.hdfs.server.blockmanagement.BlockPlacementPolicyDefault.chooseRandom(BlockPlacementPolicyDefault.java:827)
        at 
org.apache.hadoop.hdfs.server.blockmanagement.BlockPlacementPolicyDefault.chooseRandom(BlockPlacementPolicyDefault.java:715)
        at 
org.apache.hadoop.hdfs.server.blockmanagement.BlockPlacementPolicyDefault.chooseLocalRack(BlockPlacementPolicyDefault.java:622)
        at 
org.apache.hadoop.hdfs.server.blockmanagement.BlockPlacementPolicyDefault.chooseTargetInOrder(BlockPlacementPolicyDefault.java:506)
        at 
org.apache.hadoop.hdfs.server.blockmanagement.BlockPlacementPolicyDefault.chooseTarget(BlockPlacementPolicyDefault.java:416)
        at 
org.apache.hadoop.hdfs.server.blockmanagement.BlockPlacementPolicyDefault.chooseTarget(BlockPlacementPolicyDefault.java:465)
        at 
org.apache.hadoop.hdfs.server.blockmanagement.BlockPlacementPolicyDefault.chooseTarget(BlockPlacementPolicyDefault.java:292)
        at 
org.apache.hadoop.hdfs.server.blockmanagement.BlockPlacementPolicyDefault.chooseTarget(BlockPlacementPolicyDefault.java:143)
        at 
org.apache.hadoop.hdfs.server.blockmanagement.BlockPlacementPolicyDefault.chooseTarget(BlockPlacementPolicyDefault.java:159)
        at 
org.apache.hadoop.hdfs.server.blockmanagement.BlockManager.chooseTarget4NewBlock(BlockManager.java:2094)
        at 
org.apache.hadoop.hdfs.server.namenode.FSDirWriteFileOp.chooseTargetForNewBlock(FSDirWriteFileOp.java:294)
        at 
org.apache.hadoop.hdfs.server.namenode.FSNamesystem.getAdditionalBlock(FSNamesystem.java:2673)
        at 
org.apache.hadoop.hdfs.server.namenode.NameNodeRpcServer.addBlock(NameNodeRpcServer.java:872)
        at 
org.apache.hadoop.hdfs.protocolPB.ClientNamenodeProtocolServerSideTranslatorPB.addBlock(ClientNamenodeProtocolServerSideTranslatorPB.java:550)
        at 
org.apache.hadoop.hdfs.protocol.proto.ClientNamenodeProtocolProtos$ClientNamenodeProtocol$2.callBlockingMethod(ClientNamenodeProtocolProtos.java)
        at 
org.apache.hadoop.ipc.ProtobufRpcEngine$Server$ProtoBufRpcInvoker.call(ProtobufRpcEngine.java:523)
        at org.apache.hadoop.ipc.RPC$Server.call(RPC.java:991)
        at org.apache.hadoop.ipc.Server$RpcCall.run(Server.java:869)
        at org.apache.hadoop.ipc.Server$RpcCall.run(Server.java:815)
        at 
java.base/java.security.AccessController.doPrivileged(AccessController.java:691)
        at java.base/javax.security.auth.Subject.doAs(Subject.java:423)
        at 
org.apache.hadoop.security.UserGroupInformation.doAs(UserGroupInformation.java:1875)
        at org.apache.hadoop.ipc.Server$Handler.run(Server.java:2675)
2023-03-30 12:22:53,301 DEBUG org.apache.hadoop.net.NetworkTopology: Choosing 
random from 1 available nodes on node /TX/T01/02, scope=/TX/T01/02, 
excludedScope=null, excludeNodes=[x.x.x.x:9866, x.x.x.x:9866]. numOfDatanodes=2.
2023-03-30 12:22:53,301 DEBUG org.apache.hadoop.net.NetworkTopology: 
nthValidToReturn is 0
2023-03-30 12:22:53,301 DEBUG org.apache.hadoop.net.NetworkTopology: 
chooseRandom returning x.x.x.x:9866
2023-03-30 12:22:53,301 INFO org.apache.hadoop.hdfs.StateChange: BLOCK* 
allocate blk_1109782686_36041897, replicas=x.x.x.x:9866, x.x.x.x:9866, 
x.x.x.x:9866 for 
/hbase/WALs/hbase-virgo-rs-12.bigdata.bj.tx.lan,16020,1679299081702/hbase-virgo-rs-12.bigdata.bj.tx.lan%2C16020%2C1679299081702.hbase-virgo-rs-12.bigdata.bj.tx.lan%2C16020%2C1679299081702.regiongroup-0.1680150171428
2023-03-30 12:22:53,311 INFO org.apache.hadoop.hdfs.StateChange: DIR* 
completeFile: 
/hbase/WALs/hbase-virgo-rs-18.bigdata.bj.tx.lan,16020,1679431900739/hbase-virgo-rs-18.bigdata.bj.tx.lan%2C16020%2C1679431900739.hbase-virgo-rs-18.bigdata.bj.tx.lan%2C16020%2C1679431900739.regiongroup-0.1680149941088
 is closed by DFSClient_NONMAPREDUCE_-1935786627_1
2023-03-30 12:22:53,311 DEBUG org.apache.hadoop.net.NetworkTopology: Choosing 
random from 13 available nodes on node /, scope=, excludedScope=/TX/T01/03, 
excludeNodes=[x.x.x.x:9866]. numOfDatanodes=13.
2023-03-30 12:22:53,311 DEBUG org.apache.hadoop.net.NetworkTopology: 
nthValidToReturn is 6
2023-03-30 12:22:53,311 DEBUG org.apache.hadoop.net.NetworkTopology: Chosen 
node x.x.x.x:9866 from first random
2023-03-30 12:22:53,311 DEBUG org.apache.hadoop.net.NetworkTopology: 
chooseRandom returning x.x.x.x:9866
2023-03-30 12:22:53,311 DEBUG org.apache.hadoop.net.NetworkTopology: Choosing 
random from 3 available nodes on node /TX/T01/04, scope=/TX/T01/04, 
excludedScope=null, excludeNodes=[x.x.x.x:9866, x.x.x.x:9866]. numOfDatanodes=4.



















在 2023-03-29 22:00:18,"张铎(Duo Zhang)" <palomino...@gmail.com> 写道:
>这个要看你 flush 出去的数据有多大吧?以及写 HDFS 的速度,十几秒通常看还行吧,不算特别慢。有监控打 snapshot 时候集群的整体负载和
>IO 情况吗?
>
>邢* <xingxuem...@163.com> 于2023年3月29日周三 19:20写道:
>
>> hi all,
>>
>>
>> 向社区求助一个HBase的情况,情况描述如下:我们hbase集群某张大表最近做snapshot的时间过长,耗时约半小时。梳理日志发现每个region
>> flush的时间在十几秒左右,想咨询下flush的时间为什么会这么久?
>>
>>     集群现状:目前是有14台cpu内存都是96c 384g机型的regionServer机器+3台cpu内存都是8c
>> 32g机型的zookeeper机器,使用的hbase版本为2.1.9。
>>
>>     最近排查到的日志记录如下:
>>
>>     regionserver DFSClient 日志详情:
>>
>>     2023-03-29 16:24:55,395 INFO org.apache.hadoop.hdfs.DFSClient: Could
>> not complete
>> /hbase/.hbase-snapshot/.tmp/sdhz_user_info_realtime_1680076952828/region-manifest.603b4d8028af279648af4bfaa3889fd0
>> retrying...
>>
>>     namenode日志详情:
>>
>>     2023-03-29 16:24:54,995 INFO
>> org.apache.hadoop.hdfs.server.namenode.FSNamesystem: BLOCK*
>> blk_1109699571_35958782 is COMMITTED but not COMPLETE(numNodes= 0 <
>> minimum = 1) in file
>> /hbase/.hbase-snapshot/.tmp/sdhz_user_info_realtime_1680076952828/region-manifest.603b4d8028af279648af4bfaa3889fd0

Reply via email to