You are viewing a plain text version of this content. The canonical link for it is here.
Posted to hdfs-issues@hadoop.apache.org by "Jason Pyeron (Jira)" <ji...@apache.org> on 2025/01/05 02:13:00 UTC
[jira] [Commented] (HDFS-17673) Unable to run HDFS balancer as a service
[ https://issues.apache.org/jira/browse/HDFS-17673?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17909810#comment-17909810 ]
Jason Pyeron commented on HDFS-17673:
-------------------------------------
also occurs in 3.4.1.
running {{hdfs balancer}} results in (some details have been redacted)
{noformat}
[hadoop@NAMENODE hadoop]$ hdfs balancer
2025-01-04 20:58:20,649 INFO impl.MetricsConfig: Loaded properties from hadoop-metrics2.properties
2025-01-04 20:58:20,897 INFO impl.MetricsSystemImpl: Scheduled Metric snapshot period at 10 second(s).
2025-01-04 20:58:20,897 INFO impl.MetricsSystemImpl: Balancer metrics system started
2025-01-04 20:58:20,941 INFO balancer.Balancer: namenodes = [hdfs://NAMENODE:9000]
2025-01-04 20:58:20,945 INFO balancer.Balancer: parameters = Balancer.BalancerParameters [BalancingPolicy.Node, threshold = 10.0, max idle iteration = 5, #excluded nodes = 0, #included nodes = 0, #source nodes = 0, #blockpools = 0, run during upgrade = false, sort top nodes = false, hot block time interval = 0]
2025-01-04 20:58:20,945 INFO balancer.Balancer: included nodes = []
2025-01-04 20:58:20,945 INFO balancer.Balancer: excluded nodes = []
2025-01-04 20:58:20,945 INFO balancer.Balancer: source nodes = []
Time Stamp Iteration# Bytes Already Moved Bytes Left To Move Bytes Being Moved NameNode
2025-01-04 20:58:20,950 INFO balancer.NameNodeConnector: getBlocks calls for hdfs://NAMENODE:9000 will be rate-limited to 20 per second
2025-01-04 20:58:22,762 INFO balancer.Balancer: dfs.namenode.get-blocks.max-qps = 20 (default=20)
2025-01-04 20:58:22,762 INFO balancer.Balancer: dfs.balancer.movedWinWidth = 5400000 (default=5400000)
2025-01-04 20:58:22,762 INFO balancer.Balancer: dfs.balancer.moverThreads = 1000 (default=1000)
2025-01-04 20:58:22,762 INFO balancer.Balancer: dfs.balancer.dispatcherThreads = 200 (default=200)
2025-01-04 20:58:22,762 INFO balancer.Balancer: dfs.balancer.getBlocks.size = 2147483648 (default=2147483648)
2025-01-04 20:58:22,762 INFO balancer.Balancer: dfs.balancer.getBlocks.min-block-size = 10485760 (default=10485760)
2025-01-04 20:58:22,763 INFO balancer.Balancer: dfs.datanode.balance.max.concurrent.moves = 100 (default=100)
2025-01-04 20:58:22,763 INFO balancer.Balancer: dfs.datanode.balance.bandwidthPerSec = 104857600 (default=104857600)
2025-01-04 20:58:22,771 INFO balancer.Balancer: dfs.balancer.max-size-to-move = 10737418240 (default=10737418240)
2025-01-04 20:58:22,771 INFO balancer.Balancer: dfs.blocksize = 134217728 (default=134217728)
2025-01-04 20:58:22,813 INFO net.NetworkTopology: Adding a new node: /default-rack/datanode-194:9866
...REDACTED...
2025-01-04 20:58:22,817 INFO net.NetworkTopology: Adding a new node: /default-rack/datanode-167:9866
2025-01-04 20:58:22,821 INFO balancer.Balancer: 5 over-utilized: [datanode-54:9866:DISK, datanode-15:9866:DISK, datanode-152:9866:DISK, datanode-179:9866:DISK, datanode-13:9866:DISK]
2025-01-04 20:58:22,821 INFO balancer.Balancer: 4 underutilized: [datanode-187:9866:DISK, datanode-236:9866:DISK, datanode-180:9866:DISK, datanode-179:9866:DISK]
2025-01-04 20:58:22,822 INFO balancer.Balancer: Need to move 167.84 GB to make the cluster balanced.
2025-01-04 20:58:22,840 INFO balancer.Balancer: chooseStorageGroups for SAME_RACK: overUtilized => underUtilized
2025-01-04 20:58:22,841 INFO balancer.Balancer: Decided to move 10 GB bytes from datanode-54:9866:DISK to datanode-187:9866:DISK
2025-01-04 20:58:22,842 INFO balancer.Balancer: Decided to move 10 GB bytes from datanode-15:9866:DISK to datanode-236:9866:DISK
2025-01-04 20:58:22,842 INFO balancer.Balancer: Decided to move 10 GB bytes from datanode-152:9866:DISK to datanode-180:9866:DISK
2025-01-04 20:58:22,842 INFO balancer.Balancer: Decided to move 10 GB bytes from datanode-179:9866:DISK to datanode-179:9866:DISK
2025-01-04 20:58:22,842 INFO balancer.Balancer: chooseStorageGroups for SAME_RACK: overUtilized => belowAvgUtilized
2025-01-04 20:58:22,842 INFO balancer.Balancer: chooseStorageGroups for SAME_RACK: underUtilized => aboveAvgUtilized
2025-01-04 20:58:22,842 INFO balancer.Balancer: chooseStorageGroups for ANY_OTHER: overUtilized => underUtilized
2025-01-04 20:58:22,842 INFO balancer.Balancer: chooseStorageGroups for ANY_OTHER: overUtilized => belowAvgUtilized
2025-01-04 20:58:22,842 INFO balancer.Balancer: chooseStorageGroups for ANY_OTHER: underUtilized => aboveAvgUtilized
2025-01-04 20:58:22,842 INFO balancer.Balancer: Will move 40 GB in this iteration for NameNodeConnector[namenodeUri=hdfs://NAMENODE:9000, bpid=BP-391587423-datanode-118-1666125691850]
2025-01-04 20:58:22,842 INFO balancer.Balancer: Total target DataNodes in this iteration: 4
2025-01-04 20:58:22,843 INFO balancer.Dispatcher: Balancer concurrent dispatcher threads = 4
2025-01-04 20:58:22,843 INFO balancer.Dispatcher: Limiting threads per target to the specified max.
2025-01-04 20:58:22,843 INFO balancer.Dispatcher: Allocating 100 threads per target.
2025-01-04 20:58:22,891 INFO balancer.Dispatcher: Start moving blk_1073868187_127371 with size=134217728 from datanode-152:9866:DISK to datanode-180:9866:DISK through datanode-152:9866
2025-01-04 20:58:22,894 INFO balancer.Dispatcher: Start moving blk_1073868138_127322 with size=134217728 from datanode-152:9866:DISK to datanode-180:9866:DISK through datanode-152:9866
2025-01-04 20:58:22,894 INFO balancer.Dispatcher: Start moving blk_1073868125_127309 with size=60493448 from datanode-152:9866:DISK to datanode-180:9866:DISK through datanode-152:9866
2025-01-04 20:58:22,894 INFO balancer.Dispatcher: Start moving blk_1073868132_127316 with size=134217728 from datanode-152:9866:DISK to datanode-180:9866:DISK through datanode-152:9866
2025-01-04 20:58:22,893 INFO balancer.Dispatcher: Start moving blk_1073868147_127331 with size=134217728 from datanode-152:9866:DISK to datanode-180:9866:DISK through datanode-152:9866
2025-01-04 20:58:22,893 INFO balancer.Dispatcher: Start moving blk_1073868152_127336 with size=61938955 from datanode-152:9866:DISK to datanode-180:9866:DISK through datanode-152:9866
2025-01-04 20:58:22,893 INFO balancer.Dispatcher: Start moving blk_1073868156_127340 with size=52735307 from datanode-152:9866:DISK to datanode-180:9866:DISK through datanode-152:9866
2025-01-04 20:58:22,892 INFO balancer.Dispatcher: Start moving blk_1073868169_127353 with size=134217728 from datanode-152:9866:DISK to datanode-180:9866:DISK through datanode-152:9866
2025-01-04 20:58:22,896 INFO balancer.Dispatcher: Start moving blk_1073868124_127308 with size=61242733 from datanode-152:9866:DISK to datanode-180:9866:DISK through datanode-152:9866
2025-01-04 20:58:22,912 INFO balancer.Dispatcher: Start moving blk_1073868003_127187 with size=134217728 from datanode-152:9866:DISK to datanode-180:9866:DISK through datanode-152:9866
2025-01-04 20:58:22,912 INFO balancer.Dispatcher: Start moving blk_1073868005_127189 with size=134217728 from datanode-152:9866:DISK to datanode-180:9866:DISK through datanode-152:9866
2025-01-04 20:58:22,911 INFO balancer.Dispatcher: Start moving blk_1073868014_127198 with size=59247100 from datanode-152:9866:DISK to datanode-180:9866:DISK through datanode-152:9866
2025-01-04 20:58:22,911 INFO balancer.Dispatcher: Start moving blk_1073868022_127206 with size=134217728 from datanode-152:9866:DISK to datanode-180:9866:DISK through datanode-152:9866
2025-01-04 20:58:22,911 INFO balancer.Dispatcher: Start moving blk_1073868031_127215 with size=134217728 from datanode-152:9866:DISK to datanode-180:9866:DISK through datanode-152:9866
2025-01-04 20:58:22,911 INFO balancer.Dispatcher: Start moving blk_1073868050_127234 with size=134217728 from datanode-152:9866:DISK to datanode-180:9866:DISK through datanode-152:9866
2025-01-04 20:58:22,910 INFO balancer.Dispatcher: Start moving blk_1073868056_127240 with size=134217728 from datanode-152:9866:DISK to datanode-180:9866:DISK through datanode-152:9866
2025-01-04 20:58:22,910 INFO balancer.Dispatcher: Start moving blk_1073868068_127252 with size=61202594 from datanode-152:9866:DISK to datanode-180:9866:DISK through datanode-152:9866
2025-01-04 20:58:22,910 INFO balancer.Dispatcher: Start moving blk_1073868085_127269 with size=134217728 from datanode-152:9866:DISK to datanode-180:9866:DISK through datanode-152:9866
2025-01-04 20:58:22,909 INFO balancer.Dispatcher: Start moving blk_1073868121_127305 with size=134217728 from datanode-152:9866:DISK to datanode-180:9866:DISK through datanode-152:9866
2025-01-04 20:58:22,900 INFO balancer.Dispatcher: Start moving blk_1073868104_127288 with size=134217728 from datanode-152:9866:DISK to datanode-180:9866:DISK through datanode-152:9866
2025-01-04 20:58:34,187 INFO balancer.Dispatcher: Successfully moved blk_1073868156_127340 with size=52735307 from datanode-152:9866:DISK to datanode-180:9866:DISK through datanode-152:9866
2025-01-04 20:58:35,134 INFO balancer.Dispatcher: Successfully moved blk_1073868014_127198 with size=59247100 from datanode-152:9866:DISK to datanode-180:9866:DISK through datanode-152:9866
2025-01-04 20:58:35,423 INFO balancer.Dispatcher: Successfully moved blk_1073868125_127309 with size=60493448 from datanode-152:9866:DISK to datanode-180:9866:DISK through datanode-152:9866
2025-01-04 20:58:35,504 INFO balancer.Dispatcher: Successfully moved blk_1073868068_127252 with size=61202594 from datanode-152:9866:DISK to datanode-180:9866:DISK through datanode-152:9866
2025-01-04 20:58:35,571 INFO balancer.Dispatcher: Successfully moved blk_1073868124_127308 with size=61242733 from datanode-152:9866:DISK to datanode-180:9866:DISK through datanode-152:9866
2025-01-04 20:58:35,588 INFO balancer.Dispatcher: Successfully moved blk_1073868152_127336 with size=61938955 from datanode-152:9866:DISK to datanode-180:9866:DISK through datanode-152:9866
2025-01-04 20:58:44,991 INFO balancer.Dispatcher: Successfully moved blk_1073868031_127215 with size=134217728 from datanode-152:9866:DISK to datanode-180:9866:DISK through datanode-152:9866
2025-01-04 20:58:44,994 INFO balancer.Dispatcher: Successfully moved blk_1073868003_127187 with size=134217728 from datanode-152:9866:DISK to datanode-180:9866:DISK through datanode-152:9866
2025-01-04 20:58:45,007 INFO balancer.Dispatcher: Successfully moved blk_1073868056_127240 with size=134217728 from datanode-152:9866:DISK to datanode-180:9866:DISK through datanode-152:9866
2025-01-04 20:58:45,022 INFO balancer.Dispatcher: Successfully moved blk_1073868169_127353 with size=134217728 from datanode-152:9866:DISK to datanode-180:9866:DISK through datanode-152:9866
2025-01-04 20:58:45,109 INFO balancer.Dispatcher: Successfully moved blk_1073868187_127371 with size=134217728 from datanode-152:9866:DISK to datanode-180:9866:DISK through datanode-152:9866
2025-01-04 20:58:45,120 INFO balancer.Dispatcher: Successfully moved blk_1073868121_127305 with size=134217728 from datanode-152:9866:DISK to datanode-180:9866:DISK through datanode-152:9866
2025-01-04 20:58:45,133 INFO balancer.Dispatcher: Successfully moved blk_1073868005_127189 with size=134217728 from datanode-152:9866:DISK to datanode-180:9866:DISK through datanode-152:9866
2025-01-04 20:58:45,140 INFO balancer.Dispatcher: Successfully moved blk_1073868050_127234 with size=134217728 from datanode-152:9866:DISK to datanode-180:9866:DISK through datanode-152:9866
2025-01-04 20:58:45,149 INFO balancer.Dispatcher: Successfully moved blk_1073868085_127269 with size=134217728 from datanode-152:9866:DISK to datanode-180:9866:DISK through datanode-152:9866
2025-01-04 20:58:45,166 INFO balancer.Dispatcher: Successfully moved blk_1073868022_127206 with size=134217728 from datanode-152:9866:DISK to datanode-180:9866:DISK through datanode-152:9866
2025-01-04 20:58:45,180 INFO balancer.Dispatcher: Successfully moved blk_1073868132_127316 with size=134217728 from datanode-152:9866:DISK to datanode-180:9866:DISK through datanode-152:9866
2025-01-04 20:58:45,182 INFO balancer.Dispatcher: Successfully moved blk_1073868138_127322 with size=134217728 from datanode-152:9866:DISK to datanode-180:9866:DISK through datanode-152:9866
2025-01-04 20:58:45,183 INFO balancer.Dispatcher: Successfully moved blk_1073868104_127288 with size=134217728 from datanode-152:9866:DISK to datanode-180:9866:DISK through datanode-152:9866
2025-01-04 20:58:45,189 INFO balancer.Dispatcher: Successfully moved blk_1073868147_127331 with size=134217728 from datanode-152:9866:DISK to datanode-180:9866:DISK through datanode-152:9866
2025-01-04 20:58:46,033 INFO balancer.Dispatcher: Total bytes (blocks) moved in this iteration 2.08 GB (20)
Jan 4, 2025, 8:58:46 PM 0 2.08 GB 167.84 GB 40 GB 20 hdfs://NAMENODE:9000
2025-01-04 20:58:55,054 INFO balancer.Balancer: dfs.namenode.get-blocks.max-qps = 20 (default=20)
2025-01-04 20:58:55,054 INFO balancer.Balancer: dfs.balancer.movedWinWidth = 5400000 (default=5400000)
2025-01-04 20:58:55,054 INFO balancer.Balancer: dfs.balancer.moverThreads = 1000 (default=1000)
2025-01-04 20:58:55,054 INFO balancer.Balancer: dfs.balancer.dispatcherThreads = 200 (default=200)
2025-01-04 20:58:55,054 INFO balancer.Balancer: dfs.balancer.getBlocks.size = 2147483648 (default=2147483648)
2025-01-04 20:58:55,054 INFO balancer.Balancer: dfs.balancer.getBlocks.min-block-size = 10485760 (default=10485760)
2025-01-04 20:58:55,055 INFO balancer.Balancer: dfs.datanode.balance.max.concurrent.moves = 100 (default=100)
2025-01-04 20:58:55,055 INFO balancer.Balancer: dfs.datanode.balance.bandwidthPerSec = 104857600 (default=104857600)
2025-01-04 20:58:55,055 INFO balancer.Balancer: dfs.balancer.max-size-to-move = 10737418240 (default=10737418240)
2025-01-04 20:58:55,055 INFO balancer.Balancer: dfs.blocksize = 134217728 (default=134217728)
Jan 4, 2025, 8:58:55 PM Balancing took 35.618 seconds
2025-01-04 20:58:55,732 ERROR balancer.Balancer: Exiting balancer due an exception
org.apache.hadoop.metrics2.MetricsException: Metrics source Balancer-BP-391587423-datanode-118-1666125691850 already exists!
at org.apache.hadoop.metrics2.lib.DefaultMetricsSystem.newSourceName(DefaultMetricsSystem.java:152)
at org.apache.hadoop.metrics2.lib.DefaultMetricsSystem.sourceName(DefaultMetricsSystem.java:125)
at org.apache.hadoop.metrics2.impl.MetricsSystemImpl.register(MetricsSystemImpl.java:229)
at org.apache.hadoop.hdfs.server.balancer.BalancerMetrics.create(BalancerMetrics.java:52)
at org.apache.hadoop.hdfs.server.balancer.Balancer.<init>(Balancer.java:362)
at org.apache.hadoop.hdfs.server.balancer.Balancer.doBalance(Balancer.java:824)
at org.apache.hadoop.hdfs.server.balancer.Balancer.run(Balancer.java:868)
at org.apache.hadoop.hdfs.server.balancer.Balancer$Cli.run(Balancer.java:975)
at org.apache.hadoop.util.ToolRunner.run(ToolRunner.java:82)
at org.apache.hadoop.hdfs.server.balancer.Balancer.main(Balancer.java:1133) {noformat}
> Unable to run HDFS balancer as a service
> ----------------------------------------
>
> Key: HDFS-17673
> URL: https://issues.apache.org/jira/browse/HDFS-17673
> Project: Hadoop HDFS
> Issue Type: Bug
> Components: balancer & mover
> Affects Versions: 3.4.0
> Reporter: Dirk Daems
> Priority: Major
>
> When running the HDFS balancer as a service using the following command
>
> {code:java}
> hdfs balancer -asService {code}
> the first balancing round succeeds:
> {code:java}
> $ hdfs balancer -asService
> 2024-11-25 14:58:14,712 INFO balancer.Balancer: Balancer will run as a long running service
> 2024-11-25 14:58:14,764 INFO impl.MetricsConfig: Loaded properties from hadoop-metrics2.properties
> 2024-11-25 14:58:14,824 INFO impl.MetricsSystemImpl: Scheduled Metric snapshot period at 10 second(s).
> 2024-11-25 14:58:14,824 INFO impl.MetricsSystemImpl: Balancer metrics system started
> 2024-11-25 14:58:14,840 INFO balancer.Balancer: namenodes = [hdfs://prd]
> 2024-11-25 14:58:14,841 INFO balancer.Balancer: parameters = Balancer.BalancerParameters [BalancingPolicy.Node, threshold = 10.0, max idle iteration = 5, #excluded nodes = 0, #included nodes = 0, #source nodes = 0, #blockpools = 0, run during upgrade = false, sort top nodes = false, hot block time interval = 0]
> 2024-11-25 14:58:14,841 INFO balancer.Balancer: included nodes = []
> 2024-11-25 14:58:14,841 INFO balancer.Balancer: excluded nodes = []
> 2024-11-25 14:58:14,841 INFO balancer.Balancer: source nodes = []
> 2024-11-25 14:58:14,841 INFO balancer.Balancer: Keytab is configured, will login using keytab.
> 2024-11-25 14:58:14,955 INFO security.UserGroupInformation: Login successful for user hdfs@VGT.VITO.BE using keytab file hdfs.headless.keytab. Keytab auto renewal enabled : false
> Time Stamp Iteration# Bytes Already Moved Bytes Left To Move Bytes Being Moved NameNode
> 2024-11-25 14:58:14,956 INFO balancer.NameNodeConnector: getBlocks calls for hdfs://prd will be rate-limited to 20 per second
> 2024-11-25 14:58:15,499 INFO balancer.KeyManager: Block token params received from NN: update interval=10hrs, 0sec, token lifetime=10hrs, 0sec
> 2024-11-25 14:58:15,501 INFO block.BlockTokenSecretManager: Block token key range: [0, 2147483647)
> 2024-11-25 14:58:15,501 INFO block.BlockTokenSecretManager: Setting block keys. BlockPool = BP-1957577775-192.168.146.236-1720512277934 .
> 2024-11-25 14:58:15,501 INFO balancer.KeyManager: Update block keys every 2hrs, 30mins, 0sec
> 2024-11-25 14:58:15,702 INFO balancer.Balancer: dfs.namenode.get-blocks.max-qps = 20 (default=20)
> 2024-11-25 14:58:15,703 INFO balancer.Balancer: dfs.balancer.movedWinWidth = 5400000 (default=5400000)
> 2024-11-25 14:58:15,703 INFO balancer.Balancer: dfs.balancer.moverThreads = 1000 (default=1000)
> 2024-11-25 14:58:15,703 INFO balancer.Balancer: dfs.balancer.dispatcherThreads = 200 (default=200)
> 2024-11-25 14:58:15,703 INFO balancer.Balancer: dfs.balancer.getBlocks.size = 2147483648 (default=2147483648)
> 2024-11-25 14:58:15,703 INFO balancer.Balancer: dfs.balancer.getBlocks.min-block-size = 10485760 (default=10485760)
> 2024-11-25 14:58:15,703 INFO balancer.Balancer: dfs.datanode.balance.max.concurrent.moves = 100 (default=100)
> 2024-11-25 14:58:15,703 INFO balancer.Balancer: dfs.datanode.balance.bandwidthPerSec = 104857600 (default=104857600)
> 2024-11-25 14:58:15,705 INFO block.BlockTokenSecretManager: Setting block keys. BlockPool = BP-1957577775-192.168.146.236-1720512277934 .
> 2024-11-25 14:58:15,708 INFO balancer.Balancer: dfs.balancer.max-size-to-move = 10737418240 (default=10737418240)
> 2024-11-25 14:58:15,708 INFO balancer.Balancer: dfs.blocksize = 268435456 (default=134217728)
> 2024-11-25 14:58:15,732 INFO net.NetworkTopology: Adding a new node: /LeibnizRack17/192.168.146.15:10004
> 2024-11-25 14:58:15,733 INFO net.NetworkTopology: Adding a new node: /LeibnizRack17/192.168.146.16:10004
> 2024-11-25 14:58:15,733 INFO net.NetworkTopology: Adding a new node: /LeibnizRack17/192.168.146.14:10004
> 2024-11-25 14:58:15,733 INFO net.NetworkTopology: Adding a new node: /LeibnizRack17/192.168.146.13:10004
> 2024-11-25 14:58:15,733 INFO net.NetworkTopology: Adding a new node: /LeibnizRack17/192.168.146.248:10004
> 2024-11-25 14:58:15,734 INFO balancer.Balancer: 0 over-utilized: []
> 2024-11-25 14:58:15,734 INFO balancer.Balancer: 0 underutilized: []
> Nov 25, 2024, 2:58:15 PM 0 0 B 0 B 0 B 0 hdfs://prd
> The cluster is balanced. Exiting...
> 2024-11-25 14:58:15,751 INFO balancer.Balancer: Balance succeed!
> 2024-11-25 14:58:15,751 INFO balancer.Balancer: Finished one round, will wait for 5.0 minutes for next round{code}
> but subsequent rounds always fail with:
> {code:java}
> 2024-11-25 15:03:15,751 INFO balancer.Balancer: namenodes = [hdfs://prd]
> 2024-11-25 15:03:15,751 INFO balancer.Balancer: parameters = Balancer.BalancerParameters [BalancingPolicy.Node, threshold = 10.0, max idle iteration = 5, #excluded nodes = 0, #included nodes = 0, #source nodes = 0, #blockpools = 0, run during upgrade = false, sort top nodes = false, hot block time interval = 0]
> 2024-11-25 15:03:15,751 INFO balancer.Balancer: included nodes = []
> 2024-11-25 15:03:15,751 INFO balancer.Balancer: excluded nodes = []
> 2024-11-25 15:03:15,752 INFO balancer.Balancer: source nodes = []
> 2024-11-25 15:03:15,752 INFO balancer.Balancer: Keytab is configured, will login using keytab.
> 2024-11-25 15:03:15,792 INFO security.UserGroupInformation: Login successful for user hdfs@VGT.VITO.BE using keytab file hdfs.headless.keytab. Keytab auto renewal enabled : false
> Time Stamp Iteration# Bytes Already Moved Bytes Left To Move Bytes Being Moved NameNode
> 2024-11-25 15:03:15,792 INFO balancer.NameNodeConnector: getBlocks calls for hdfs://prd will be rate-limited to 20 per second
> 2024-11-25 15:03:15,909 INFO balancer.KeyManager: Block token params received from NN: update interval=10hrs, 0sec, token lifetime=10hrs, 0sec
> 2024-11-25 15:03:15,909 INFO block.BlockTokenSecretManager: Block token key range: [0, 2147483647)
> 2024-11-25 15:03:15,909 INFO block.BlockTokenSecretManager: Setting block keys. BlockPool = BP-1957577775-192.168.146.236-1720512277934 .
> 2024-11-25 15:03:15,909 INFO balancer.KeyManager: Update block keys every 2hrs, 30mins, 0sec
> 2024-11-25 15:03:15,934 INFO balancer.Balancer: dfs.namenode.get-blocks.max-qps = 20 (default=20)
> 2024-11-25 15:03:15,934 INFO balancer.Balancer: dfs.balancer.movedWinWidth = 5400000 (default=5400000)
> 2024-11-25 15:03:15,934 INFO balancer.Balancer: dfs.balancer.moverThreads = 1000 (default=1000)
> 2024-11-25 15:03:15,934 INFO balancer.Balancer: dfs.balancer.dispatcherThreads = 200 (default=200)
> 2024-11-25 15:03:15,934 INFO balancer.Balancer: dfs.balancer.getBlocks.size = 2147483648 (default=2147483648)
> 2024-11-25 15:03:15,934 INFO balancer.Balancer: dfs.balancer.getBlocks.min-block-size = 10485760 (default=10485760)
> 2024-11-25 15:03:15,935 INFO balancer.Balancer: dfs.datanode.balance.max.concurrent.moves = 100 (default=100)
> 2024-11-25 15:03:15,935 INFO balancer.Balancer: dfs.datanode.balance.bandwidthPerSec = 104857600 (default=104857600)
> 2024-11-25 15:03:15,936 INFO block.BlockTokenSecretManager: Setting block keys. BlockPool = BP-1957577775-192.168.146.236-1720512277934 .
> 2024-11-25 15:03:15,936 INFO balancer.Balancer: dfs.balancer.max-size-to-move = 10737418240 (default=10737418240)
> 2024-11-25 15:03:15,936 INFO balancer.Balancer: dfs.blocksize = 268435456 (default=134217728)
> 2024-11-25 15:03:15,945 WARN balancer.Balancer: Encounter exception while do balance work. Already tried 1 times
> org.apache.hadoop.metrics2.MetricsException: Metrics source Balancer-BP-1957577775-192.168.146.236-1720512277934 already exists!
> at org.apache.hadoop.metrics2.lib.DefaultMetricsSystem.newSourceName(DefaultMetricsSystem.java:152)
> at org.apache.hadoop.metrics2.lib.DefaultMetricsSystem.sourceName(DefaultMetricsSystem.java:125)
> at org.apache.hadoop.metrics2.impl.MetricsSystemImpl.register(MetricsSystemImpl.java:229)
> at org.apache.hadoop.hdfs.server.balancer.BalancerMetrics.create(BalancerMetrics.java:52)
> at org.apache.hadoop.hdfs.server.balancer.Balancer.<init>(Balancer.java:362)
> at org.apache.hadoop.hdfs.server.balancer.Balancer.doBalance(Balancer.java:824)
> at org.apache.hadoop.hdfs.server.balancer.Balancer.run(Balancer.java:887)
> at org.apache.hadoop.hdfs.server.balancer.Balancer$Cli.run(Balancer.java:975)
> at org.apache.hadoop.util.ToolRunner.run(ToolRunner.java:82)
> at org.apache.hadoop.hdfs.server.balancer.Balancer.main(Balancer.java:1133)
> 2024-11-25 15:03:15,946 INFO balancer.Balancer: Finished one round, will wait for 5.0 minutes for next round {code}
> and finally the process stops after retrying 5 times:
> {code:java}
> 2024-11-25 15:28:17,816 INFO balancer.Balancer: namenodes = [hdfs://prd]
> 2024-11-25 15:28:17,817 INFO balancer.Balancer: parameters = Balancer.BalancerParameters [BalancingPolicy.Node, threshold = 10.0, max idle iteration = 5, #excluded nodes = 0, #included nodes = 0, #source nodes = 0, #blockpools = 0, run during upgrade = false, sort top nodes = false, hot block time interval = 0]
> 2024-11-25 15:28:17,817 INFO balancer.Balancer: included nodes = []
> 2024-11-25 15:28:17,817 INFO balancer.Balancer: excluded nodes = []
> 2024-11-25 15:28:17,817 INFO balancer.Balancer: source nodes = []
> 2024-11-25 15:28:17,817 INFO balancer.Balancer: Keytab is configured, will login using keytab.
> 2024-11-25 15:28:17,853 INFO security.UserGroupInformation: Login successful for user hdfs@VGT.VITO.BE using keytab file hdfs.headless.keytab. Keytab auto renewal enabled : false
> Time Stamp Iteration# Bytes Already Moved Bytes Left To Move Bytes Being Moved NameNode
> 2024-11-25 15:28:17,853 INFO balancer.NameNodeConnector: getBlocks calls for hdfs://prd will be rate-limited to 20 per second
> 2024-11-25 15:28:17,917 INFO balancer.KeyManager: Block token params received from NN: update interval=10hrs, 0sec, token lifetime=10hrs, 0sec
> 2024-11-25 15:28:17,917 INFO block.BlockTokenSecretManager: Block token key range: [0, 2147483647)
> 2024-11-25 15:28:17,917 INFO block.BlockTokenSecretManager: Setting block keys. BlockPool = BP-1957577775-192.168.146.236-1720512277934 .
> 2024-11-25 15:28:17,917 INFO balancer.KeyManager: Update block keys every 2hrs, 30mins, 0sec
> 2024-11-25 15:28:17,938 INFO balancer.Balancer: dfs.namenode.get-blocks.max-qps = 20 (default=20)
> 2024-11-25 15:28:17,938 INFO balancer.Balancer: dfs.balancer.movedWinWidth = 5400000 (default=5400000)
> 2024-11-25 15:28:17,938 INFO balancer.Balancer: dfs.balancer.moverThreads = 1000 (default=1000)
> 2024-11-25 15:28:17,938 INFO balancer.Balancer: dfs.balancer.dispatcherThreads = 200 (default=200)
> 2024-11-25 15:28:17,938 INFO balancer.Balancer: dfs.balancer.getBlocks.size = 2147483648 (default=2147483648)
> 2024-11-25 15:28:17,938 INFO balancer.Balancer: dfs.balancer.getBlocks.min-block-size = 10485760 (default=10485760)
> 2024-11-25 15:28:17,938 INFO balancer.Balancer: dfs.datanode.balance.max.concurrent.moves = 100 (default=100)
> 2024-11-25 15:28:17,938 INFO balancer.Balancer: dfs.datanode.balance.bandwidthPerSec = 104857600 (default=104857600)
> 2024-11-25 15:28:17,940 INFO balancer.Balancer: dfs.balancer.max-size-to-move = 10737418240 (default=10737418240)
> 2024-11-25 15:28:17,940 INFO balancer.Balancer: dfs.blocksize = 268435456 (default=134217728)
> 2024-11-25 15:28:17,940 INFO block.BlockTokenSecretManager: Setting block keys. BlockPool = BP-1957577775-192.168.146.236-1720512277934 .
> Nov 25, 2024, 3:28:17 PM Balancing took 30.0581 minutes
> 2024-11-25 15:28:17,948 ERROR balancer.Balancer: Exiting balancer due an exception
> org.apache.hadoop.metrics2.MetricsException: Metrics source Balancer-BP-1957577775-192.168.146.236-1720512277934 already exists!
> at org.apache.hadoop.metrics2.lib.DefaultMetricsSystem.newSourceName(DefaultMetricsSystem.java:152)
> at org.apache.hadoop.metrics2.lib.DefaultMetricsSystem.sourceName(DefaultMetricsSystem.java:125)
> at org.apache.hadoop.metrics2.impl.MetricsSystemImpl.register(MetricsSystemImpl.java:229)
> at org.apache.hadoop.hdfs.server.balancer.BalancerMetrics.create(BalancerMetrics.java:52)
> at org.apache.hadoop.hdfs.server.balancer.Balancer.<init>(Balancer.java:362)
> at org.apache.hadoop.hdfs.server.balancer.Balancer.doBalance(Balancer.java:824)
> at org.apache.hadoop.hdfs.server.balancer.Balancer.run(Balancer.java:887)
> at org.apache.hadoop.hdfs.server.balancer.Balancer$Cli.run(Balancer.java:975)
> at org.apache.hadoop.util.ToolRunner.run(ToolRunner.java:82)
> at org.apache.hadoop.hdfs.server.balancer.Balancer.main(Balancer.java:1133)
> {code}
> Looking at the HDFS balancer code, I don't see a way to prevent this error, which is strange. A metrics source is created, with name "Balancer-" + blockpoolID, where blockpoolID is 'BP-1957577775-192.168.146.236-1720512277934' in our case.
> When in servicemode, new balancers (and thus metrics sources) will be created in the doBalance method, while the service is running.
> When looking at the metrics implementation, duplicates are only allowed when the metrics system is being started. After correct initialization of the metrics system, duplicates are no longer allowed (monitoring flag is set to true).
--
This message was sent by Atlassian Jira
(v8.20.10#820010)
---------------------------------------------------------------------
To unsubscribe, e-mail: hdfs-issues-unsubscribe@hadoop.apache.org
For additional commands, e-mail: hdfs-issues-help@hadoop.apache.org