Cannot resolve bookieId 172.30.222.17:3181 to a network address, resolving as /default-region/default-rack

[suyuNJ]

Hi:
I am currently deploying a pulsar cluster to performance test.
my pulsar version: 2.10.0
os release: Linux poc-node01 3.10.0-693.el7.x86_64
cpu 8 core
mem 16G
disk hdd
my cluster node:
poc-node01 172.30.222.16
poc-node02 172.30.222.17
poc-node03 172.30.222.18
performance test tools is pulsar perf
when exe ./bin/pulsar-perf produce -r 50000 -n 2 -s 1024 digital/logtest/test_qiqi11 command in poc-node02 (172.30.222.17）, the Latency very large.
perf log like this:
2022-09-29T22:16:27,222+0800 [pulsar-client-io-2-1] INFO com.scurrilous.circe.checksum.Crc32cIntChecksum - SSE4.2 CRC32C provider initialized
2022-09-29T22:16:35,139+0800 [main] INFO org.apache.pulsar.testclient.PerformanceProducer - Throughput produced: 96018 msg --- 9601.7 msg/s --- 75.0 Mbit/s --- failure 0.0 msg/s --- Latency: mean: 2838.564 ms - med: 2888.895 - 95pct: 5381.855 - 99pct: 5504.287 - 99.9pct: 5507.423 - 99.99pct: 5508.095 - Max: 5508.159
2022-09-29T22:16:45,316+0800 [main] INFO org.apache.pulsar.testclient.PerformanceProducer - Throughput produced: 254887 msg --- 15295.7 msg/s --- 119.5 Mbit/s --- failure 0.0 msg/s --- Latency: mean: 4744.468 ms - med: 4320.671 - 95pct: 7791.967 - 99pct: 7808.511 - 99.9pct: 7814.015 - 99.99pct: 7820.767 - Max: 9202.943
2022-09-29T22:16:55,421+0800 [main] INFO org.apache.pulsar.testclient.PerformanceProducer - Throughput produced: 297692 msg --- 4236.0 msg/s --- 33.1 Mbit/s --- failure 0.0 msg/s --- Latency: mean: 9491.497 ms - med: 11608.767 - 95pct: 11678.143 - 99pct: 11680.511 - 99.9pct: 11681.087 - 99.99pct: 11681.215 - Max: 12870.399
2022-09-29T22:17:05,535+0800 [main] INFO org.apache.pulsar.testclient.PerformanceProducer - Throughput produced: 377389 msg --- 7884.2 msg/s --- 61.6 Mbit/s --- failure 0.0 msg/s --- Latency: mean: 12339.474 ms - med: 10284.735 - 95pct: 20839.167 - 99pct: 20845.695 - 99.9pct: 20846.847 - 99.99pct: 20846.975 - Max: 21108.351
2022-09-29T22:17:15,724+0800 [main] INFO org.apache.pulsar.testclient.PerformanceProducer - Throughput produced: 506457 msg --- 12678.1 msg/s --- 99.0 Mbit/s --- failure 0.0 msg/s --- Latency: mean: 4817.731 ms - med: 5514.463 - 95pct: 6470.079 - 99pct: 6488.191 - 99.9pct: 6492.959 - 99.99pct: 6493.151 - Max: 9192.959
2022-09-29T22:17:25,813+0800 [main] INFO org.apache.pulsar.testclient.PerformanceProducer - Throughput produced: 584197 msg --- 7682.3 msg/s --- 60.0 Mbit/s --- failure 0.0 msg/s --- Latency: mean: 2691.226 ms - med: 3273.839 - 95pct: 4991.711 - 99pct: 5182.431 - 99.9pct: 5183.647 - 99.99pct: 5183.775 - Max: 5183.775
2022-09-29T22:17:26,837+0800 [pulsar-client-io-2-1] INFO org.apache.pulsar.client.impl.ConnectionPool - [[id: 0x503a73b9, L:/127.0.0.1:42186 - R:localhost/127.0.0.1:6650]] Connected to server
2022-09-29T22:17:35,928+0800 [main] INFO org.apache.pulsar.testclient.PerformanceProducer - Throughput produced: 584197 msg --- 0.0 msg/s --- 0.0 Mbit/s --- failure 0.0 msg/s --- Latency: mean: 0.000 ms - med: 0.000 - 95pct: 0.000 - 99pct: 0.000 - 99.9pct: 0.000 - 99.99pct: 0.000 - Max: 0.000
2022-09-29T22:17:46,032+0800 [main] INFO org.apache.pulsar.testclient.PerformanceProducer - Throughput produced: 783605 msg --- 19715.6 msg/s --- 154.0 Mbit/s --- failure 0.0 msg/s --- Latency: mean: 8171.410 ms - med: 2233.167 - 95pct: 21503.487 - 99pct: 21597.695 - 99.9pct: 21603.199 - 99.99pct: 21603.711 - Max: 24078.975

the following exception occurred：
2022-09-29T16:37:57,595+0800 [ReplicationWorker] INFO org.apache.bookkeeper.client.DefaultBookieAddressResolver - Cannot resolve 172.30.208.177:3181, bookie is unknown org.apache.bookkeeper.client.BKException$BKBookieHandleNotAvailableException: Bookie handle is not available
2022-09-29T16:37:57,595+0800 [ReplicationWorker] ERROR org.apache.bookkeeper.client.TopologyAwareEnsemblePlacementPolicy - Cannot resolve bookieId 172.30.222.17:3181 to a network address, resolving as /default-region/default-rack
org.apache.bookkeeper.proto.BookieAddressResolver$BookieIdNotResolvedException: Cannot resolve bookieId 172.30.222.17:3181, bookie does not exist or it is not running
at org.apache.bookkeeper.client.DefaultBookieAddressResolver.resolve(DefaultBookieAddressResolver.java:63) ~[org.apache.bookkeeper-bookkeeper-server-4.14.4.jar:4.14.4]
at org.apache.bookkeeper.client.TopologyAwareEnsemblePlacementPolicy.resolveNetworkLocation(TopologyAwareEnsemblePlacementPolicy.java:794) [org.apache.bookkeeper-bookkeeper-server-4.14.4.jar:4.14.4]
at org.apache.bookkeeper.client.TopologyAwareEnsemblePlacementPolicy.createBookieNode(TopologyAwareEnsemblePlacementPolicy.java:784) [org.apache.bookkeeper-bookkeeper-server-4.14.4.jar:4.14.4]
at org.apache.bookkeeper.client.TopologyAwareEnsemblePlacementPolicy.convertBookiesToNodes(TopologyAwareEnsemblePlacementPolicy.java:807) [org.apache.bookkeeper-bookkeeper-server-4.14.4.jar:4.14.4]
at org.apache.bookkeeper.client.RackawareEnsemblePlacementPolicyImpl.replaceBookie(RackawareEnsemblePlacementPolicyImpl.java:461) [org.apache.bookkeeper-bookkeeper-server-4.14.4.jar:4.14.4]
at org.apache.bookkeeper.client.RackawareEnsemblePlacementPolicy.replaceBookie(RackawareEnsemblePlacementPolicy.java:120) [org.apache.bookkeeper-bookkeeper-server-4.14.4.jar:4.14.4]
at org.apache.bookkeeper.client.BookKeeperAdmin.getReplacementBookiesByIndexes(BookKeeperAdmin.java:1080) [org.apache.bookkeeper-bookkeeper-server-4.14.4.jar:4.14.4]
at org.apache.bookkeeper.client.BookKeeperAdmin.replicateLedgerFragment(BookKeeperAdmin.java:1129) [org.apache.bookkeeper-bookkeeper-server-4.14.4.jar:4.14.4]
at org.apache.bookkeeper.replication.ReplicationWorker.rereplicate(ReplicationWorker.java:375) [org.apache.bookkeeper-bookkeeper-server-4.14.4.jar:4.14.4]
at org.apache.bookkeeper.replication.ReplicationWorker.rereplicate(ReplicationWorker.java:268) [org.apache.bookkeeper-bookkeeper-server-4.14.4.jar:4.14.4]
at org.apache.bookkeeper.replication.ReplicationWorker.run(ReplicationWorker.java:229) [org.apache.bookkeeper-bookkeeper-server-4.14.4.jar:4.14.4]
at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) [io.netty-netty-common-4.1.74.Final.jar:4.1.74.Final]
at java.lang.Thread.run(Thread.java:748) [?:1.8.0_201]
Caused by: org.apache.bookkeeper.client.BKException$BKBookieHandleNotAvailableException: Bookie handle is not available
at org.apache.bookkeeper.discover.ZKRegistrationClient.getBookieServiceInfo(ZKRegistrationClient.java:248) ~[org.apache.bookkeeper-bookkeeper-server-4.14.4.jar:4.14.4]
at org.apache.bookkeeper.client.DefaultBookieAddressResolver.resolve(DefaultBookieAddressResolver.java:43) ~[org.apache.bookkeeper-bookkeeper-server-4.14.4.jar:4.14.4]
... 12 more

[deployer@poc-node02 bin]$ /data/pulsar/brokers/bin/bookkeeper shell listbookies -rw
2022-09-29T22:27:27,624+0800 [main] INFO org.apache.bookkeeper.meta.MetadataDrivers - BookKeeper metadata driver manager initialized
2022-09-29T22:27:27,716+0800 [main] INFO org.apache.bookkeeper.meta.zk.ZKMetadataDriverBase - Initialize zookeeper metadata driver at metadata service uri zk+null://172.30.222.16:2181;172.30.222.17:2181;172.30.222.18:2181/ledgers : zkServers = 172.30.222.16:2181,172.30.222.17:2181,172.30.222.18:2181, ledgersRootPath = /ledgers.
2022-09-29T22:27:27,729+0800 [main] INFO org.apache.zookeeper.ZooKeeper - Client environment:zookeeper.version=3.6.3--6401e4ad2087061bc6b9f80dec2d69f2e3c8660a, built on 04/08/2021 16:35 GMT
2022-09-29T22:27:27,729+0800 [main] INFO org.apache.zookeeper.ZooKeeper - Client environment:host.name=poc-node02
2022-09-29T22:27:27,729+0800 [main] INFO org.apache.zookeeper.ZooKeeper - Client environment:java.version=1.8.0_201
2022-09-29T22:27:27,729+0800 [main] INFO org.apache.zookeeper.ZooKeeper - Client environment:java.vendor=Oracle Corporation
2022-09-29T22:27:27,729+0800 [main] INFO org.apache.zookeeper.ZooKeeper - Client environment:java.home=/usr/local/jdk1.8.0_201/jre
2022-09-29T22:27:27,729+0800 [main] INFO org.apache.zookeeper.ZooKeeper - Client environment:java.class.path=/data/pulsar/brokers/conf:::/data/pulsar/brokers/lib/com.beust-jcommander-1.78.jar:/data/pulsar/brokers/lib/com.carrotsearch-hppc-0.7.3.jar...
2022-09-29T22:27:27,731+0800 [main] INFO org.apache.zookeeper.ZooKeeper - Client environment:java.library.path=/usr/java/packages/lib/amd64:/usr/lib64:/lib64:/lib:/usr/lib
2022-09-29T22:27:27,731+0800 [main] INFO org.apache.zookeeper.ZooKeeper - Client environment:java.io.tmpdir=/tmp
2022-09-29T22:27:27,731+0800 [main] INFO org.apache.zookeeper.ZooKeeper - Client environment:java.compiler=
2022-09-29T22:27:27,731+0800 [main] INFO org.apache.zookeeper.ZooKeeper - Client environment:os.name=Linux
2022-09-29T22:27:27,731+0800 [main] INFO org.apache.zookeeper.ZooKeeper - Client environment:os.arch=amd64
2022-09-29T22:27:27,731+0800 [main] INFO org.apache.zookeeper.ZooKeeper - Client environment:os.version=3.10.0-693.el7.x86_64
2022-09-29T22:27:27,732+0800 [main] INFO org.apache.zookeeper.ZooKeeper - Client environment:user.name=deployer
2022-09-29T22:27:27,732+0800 [main] INFO org.apache.zookeeper.ZooKeeper - Client environment:user.home=/home/deployer
2022-09-29T22:27:27,732+0800 [main] INFO org.apache.zookeeper.ZooKeeper - Client environment:user.dir=/data/pulsar/brokers
2022-09-29T22:27:27,732+0800 [main] INFO org.apache.zookeeper.ZooKeeper - Client environment:os.memory.free=1903MB
2022-09-29T22:27:27,732+0800 [main] INFO org.apache.zookeeper.ZooKeeper - Client environment:os.memory.max=2048MB
2022-09-29T22:27:27,732+0800 [main] INFO org.apache.zookeeper.ZooKeeper - Client environment:os.memory.total=2048MB
2022-09-29T22:27:27,739+0800 [main] INFO org.apache.zookeeper.ZooKeeper - Initiating client connection, connectString=172.30.222.16:2181,172.30.222.17:2181,172.30.222.18:2181 sessionTimeout=30000 watcher=org.apache.bookkeeper.zookeeper.ZooKeeperWatcherBase@4f74980d
2022-09-29T22:27:27,812+0800 [main] INFO org.apache.zookeeper.common.X509Util - Setting -D jdk.tls.rejectClientInitiatedRenegotiation=true to disable client-initiated TLS renegotiation
2022-09-29T22:27:27,822+0800 [main] INFO org.apache.zookeeper.ClientCnxnSocket - jute.maxbuffer value is 1048575 Bytes
2022-09-29T22:27:27,832+0800 [main] INFO org.apache.zookeeper.ClientCnxn - zookeeper.request.timeout value is 0. feature enabled=false
2022-09-29T22:27:27,844+0800 [main-SendThread(172.30.222.18:2181)] INFO org.apache.zookeeper.ClientCnxn - Opening socket connection to server poc-node03/172.30.222.18:2181.
2022-09-29T22:27:27,844+0800 [main-SendThread(172.30.222.18:2181)] INFO org.apache.zookeeper.ClientCnxn - SASL config status: Will not attempt to authenticate using SASL (unknown error)
2022-09-29T22:27:27,850+0800 [main-SendThread(172.30.222.18:2181)] INFO org.apache.zookeeper.ClientCnxn - Socket connection established, initiating session, client: /172.30.222.17:45414, server: poc-node03/172.30.222.18:2181
2022-09-29T22:27:27,859+0800 [main-SendThread(172.30.222.18:2181)] INFO org.apache.zookeeper.ClientCnxn - Session establishment complete on server poc-node03/172.30.222.18:2181, session id = 0x300bf50b6520001, negotiated timeout = 30000
2022-09-29T22:27:27,866+0800 [main-EventThread] INFO org.apache.bookkeeper.zookeeper.ZooKeeperWatcherBase - ZooKeeper client is connected now.
2022-09-29T22:27:28,224+0800 [main-EventThread] INFO org.apache.bookkeeper.discover.ZKRegistrationClient - Update BookieInfoCache (writable bookie) 172.30.222.17:3181 -> BookieServiceInfo{properties={}, endpoints=[EndpointInfo{id=bookie, port=3181, host=172.30.222.17, protocol=bookie-rpc, auth=[], extensions=[]}]}
2022-09-29T22:27:28,225+0800 [main-EventThread] INFO org.apache.bookkeeper.discover.ZKRegistrationClient - Update BookieInfoCache (writable bookie) 172.30.222.16:3181 -> BookieServiceInfo{properties={}, endpoints=[EndpointInfo{id=bookie, port=3181, host=172.30.222.16, protocol=bookie-rpc, auth=[], extensions=[]}]}
2022-09-29T22:27:28,225+0800 [main-EventThread] INFO org.apache.bookkeeper.discover.ZKRegistrationClient - Update BookieInfoCache (writable bookie) 172.30.222.18:3181 -> BookieServiceInfo{properties={}, endpoints=[EndpointInfo{id=bookie, port=3181, host=172.30.222.18, protocol=bookie-rpc, auth=[], extensions=[]}]}
2022-09-29T22:27:28,226+0800 [main] INFO org.apache.bookkeeper.tools.cli.commands.bookies.ListBookiesCommand - ReadWrite Bookies :
2022-09-29T22:27:28,250+0800 [main] INFO org.apache.bookkeeper.tools.cli.commands.bookies.ListBookiesCommand - BookieID:172.30.222.17:3181, IP:172.30.222.17, Port:3181, Hostname:poc-node02
2022-09-29T22:27:28,251+0800 [main] INFO org.apache.bookkeeper.tools.cli.commands.bookies.ListBookiesCommand - BookieID:172.30.222.16:3181, IP:172.30.222.16, Port:3181, Hostname:poc-node01
2022-09-29T22:27:28,251+0800 [main] INFO org.apache.bookkeeper.tools.cli.commands.bookies.ListBookiesCommand - BookieID:172.30.222.18:3181, IP:172.30.222.18, Port:3181, Hostname:poc-node03
2022-09-29T22:27:28,357+0800 [main] INFO org.apache.zookeeper.ZooKeeper - Session: 0x300bf50b6520001 closed
2022-09-29T22:27:28,357+0800 [main-EventThread] INFO org.apache.zookeeper.ClientCnxn - EventThread shut down for session: 0x300bf50b6520001