ISSUE-11532: Pulsar 2.7.0+ KOP 2.7.2.x getPartitionedTopicMetadata timeout

[sijie]

Original Issue: apache#11532

---

web log

2021-08-02 14:50:20.473 [pulsar-web-47-4] INFO org.eclipse.jetty.server.RequestLog - 10.33.141.46 - - [02/Aug/2021:14:49:50 +0800] "GET /admin/v2/persistent/xxx/xxx/xsj.testtopic.0802.05-partition-13/stats?getPreciseBacklog=false&authoritative=false HTTP/1.1" 500 12267 "-" "Pulsar-Java-v2.7.0" 30260

2021-08-02 14:54:50.784 [pulsar-web-47-13] INFO org.eclipse.jetty.server.RequestLog - 10.33.141.44 - - [02/Aug/2021:14:54:21 +0800] "GET /admin/v2/persistent/WiseCloudDMQService/WiseCloudDMQAminService/xsj.testtopic.0729.01-partition-4/internalStats?metadata=false&authoritative=true HTTP/1.1" 200 4714 "-" "Pulsar-Java-v2.7.0" 29541
2021-08-02 14:54:50.784 [pulsar-web-47-32] INFO org.eclipse.jetty.server.RequestLog - 10.33.141.56 - - [02/Aug/2021:14:54:21 +0800] "GET /admin/v2/persistent/WiseCloudDMQService/WiseCloudDMQAminService/xsj.testtopic.0729.01/partitions HTTP/1.1" 200 17 "-" "Pulsar-Java-v2.7.0" 29542
2021-08-02 14:54:50.785 [pulsar-web-47-16] INFO org.eclipse.jetty.server.RequestLog - 10.33.141.56 - - [02/Aug/2021:14:54:21 +0800] "GET /admin/v2/persistent/WiseCloudDMQService/WiseCloudDMQAminService/xsj.testtopic.0729.01/partitions HTTP/1.1" 200 17 "-" "Pulsar-Java-v2.7.0" 29703

stack 1

"pulsar-web-47-4" #167 prio=5 os_prio=0 tid=0x00007fad5528d800 nid=0x2c6f waiting on condition [0x00007fad462c4000]
java.lang.Thread.State: TIMED_WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x0000000718c4b030> (a java.util.concurrent.CompletableFuture$Signaller)
at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
at java.util.concurrent.CompletableFuture$Signaller.block(CompletableFuture.java:1709)
at java.util.concurrent.ForkJoinPool.managedBlock(ForkJoinPool.java:3323)
at java.util.concurrent.CompletableFuture.timedGet(CompletableFuture.java:1788)
at java.util.concurrent.CompletableFuture.get(CompletableFuture.java:1928)
at org.apache.pulsar.broker.web.PulsarWebResource.validateGlobalNamespaceOwnership(PulsarWebResource.java:664)
at org.apache.pulsar.broker.admin.AdminResource.getPartitionedTopicMetadata(AdminResource.java:670)
at org.apache.pulsar.broker.admin.impl.PersistentTopicsBase.internalGetPartitionedMetadata(PersistentTopicsBase.java:627)
at org.apache.pulsar.broker.admin.v2.PersistentTopics.getPartitionedMetadata(PersistentTopics.java:743)
at sun.reflect.GeneratedMethodAccessor44.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at org.glassfish.jersey.server.model.internal.ResourceMethodInvocationHandlerFactory$$Lambda$320/538721498.invoke(Unknown Source)
at org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher$1.run(AbstractJavaResourceMethodDispatcher.java:124)
at org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher.invoke(AbstractJavaResourceMethodDispatcher.java:167)
at org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher.dispatch(AbstractJavaResourceMethodDispatcher.java:79)
at org.glassfish.jersey.server.model.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:469)
at org.glassfish.jersey.server.model.ResourceMethodInvoker.apply(ResourceMethodInvoker.java:391)
at org.glassfish.jersey.server.model.ResourceMethodInvoker.apply(ResourceMethodInvoker.java:80)
at org.glassfish.jersey.server.ServerRuntime$1.run(ServerRuntime.java:253)
at org.glassfish.jersey.internal.Errors$1.call(Errors.java:248)
at org.glassfish.jersey.internal.Errors$1.call(Errors.java:244)
at org.glassfish.jersey.internal.Errors.process(Errors.java:292)
at org.glassfish.jersey.internal.Errors.process(Errors.java:274)
at org.glassfish.jersey.internal.Errors.process(Errors.java:244)
at org.glassfish.jersey.process.internal.RequestScope.runInScope(RequestScope.java:265)
at org.glassfish.jersey.server.ServerRuntime.process(ServerRuntime.java:232)
at org.glassfish.jersey.server.ApplicationHandler.handle(ApplicationHandler.java:680)
at org.glassfish.jersey.servlet.WebComponent.serviceImpl(WebComponent.java:394)
at org.glassfish.jersey.servlet.WebComponent.service(WebComponent.java:346)
at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:366)
at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:319)
at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:205)
at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:791)
at org.eclipse.jetty.servlet.ServletHandler$ChainEnd.doFilter(ServletHandler.java:1626)
at org.apache.pulsar.broker.web.ResponseHandlerFilter.doFilter(ResponseHandlerFilter.java:58)
at org.eclipse.jetty.servlet.FilterHolder.doFilter(FilterHolder.java:193)
at org.eclipse.jetty.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1601)
at org.apache.pulsar.broker.web.AuthenticationFilter.doFilter(AuthenticationFilter.java:82)
at org.eclipse.jetty.servlet.FilterHolder.doFilter(FilterHolder.java:193)
at org.eclipse.jetty.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1601)
at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:548)
at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:233)
at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1624)
at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:233)
at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1435)
at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:188)
at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:501)
at org.eclipse.jetty.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1601)
at org.apache.pulsar.broker.web.AuthenticationFilter.doFilter(AuthenticationFilter.java:82)
at org.eclipse.jetty.servlet.FilterHolder.doFilter(FilterHolder.java:193)
at org.eclipse.jetty.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1601)
at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:548)
at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:233)
at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1624)
at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:233)
at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1435)
at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:188)
at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:501)
at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1594)
at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:186)
at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1350)
at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)
at org.eclipse.jetty.server.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:234)
at org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:146)
at org.eclipse.jetty.server.handler.StatisticsHandler.handle(StatisticsHandler.java:179)
at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127)
at org.eclipse.jetty.server.Server.handle(Server.java:516)
at org.eclipse.jetty.server.HttpChannel.lambda$handle$1(HttpChannel.java:388)
at org.eclipse.jetty.server.HttpChannel$$Lambda$432/1450467352.dispatch(Unknown Source)
at org.eclipse.jetty.server.HttpChannel.dispatch(HttpChannel.java:633)
at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:380)
at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:273)
at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311)
at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:105)
at org.eclipse.jetty.io.ChannelEndPoint$1.run(ChannelEndPoint.java:104)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
at java.lang.Thread.run(Thread.java:748)

stack 2

"pulsar-web-47-4" #167 prio=5 os_prio=0 tid=0x00007fad5528d800 nid=0x2c6f waiting on condition [0x00007fad462c4000]
java.lang.Thread.State: TIMED_WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x000000071b429428> (a java.util.concurrent.CompletableFuture$Signaller)
at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
at java.util.concurrent.CompletableFuture$Signaller.block(CompletableFuture.java:1709)
at java.util.concurrent.ForkJoinPool.managedBlock(ForkJoinPool.java:3323)
at java.util.concurrent.CompletableFuture.timedGet(CompletableFuture.java:1788)
at java.util.concurrent.CompletableFuture.get(CompletableFuture.java:1928)
at org.apache.pulsar.broker.web.PulsarWebResource.validateGlobalNamespaceOwnership(PulsarWebResource.java:664)
at org.apache.pulsar.broker.admin.AdminResource.getPartitionedTopicMetadata(AdminResource.java:670)
at org.apache.pulsar.broker.admin.impl.PersistentTopicsBase.internalGetPartitionedMetadata(PersistentTopicsBase.java:627)
at org.apache.pulsar.broker.admin.v2.PersistentTopics.getPartitionedMetadata(PersistentTopics.java:743)
at sun.reflect.GeneratedMethodAccessor44.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at org.glassfish.jersey.server.model.internal.ResourceMethodInvocationHandlerFactory.lambda$static$0(ResourceMethodInvocationHandlerFactory.java:52)
at org.glassfish.jersey.server.model.internal.ResourceMethodInvocationHandlerFactory$$Lambda$320/538721498.invoke(Unknown Source)
at org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher$1.run(AbstractJavaResourceMethodDispatcher.java:124)
at org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher.invoke(AbstractJavaResourceMethodDispatcher.java:167)
at org.glassfish.jersey.server.model.internal.JavaResourceMethodDispatcherProvider$TypeOutInvoker.doDispatch(JavaResourceMethodDispatcherProvider.java:219)
at org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher.dispatch(AbstractJavaResourceMethodDispatcher.java:79)
at org.glassfish.jersey.server.model.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:469)
at org.glassfish.jersey.server.model.ResourceMethodInvoker.apply(ResourceMethodInvoker.java:391)
at org.glassfish.jersey.server.model.ResourceMethodInvoker.apply(ResourceMethodInvoker.java:80)
at org.glassfish.jersey.server.ServerRuntime$1.run(ServerRuntime.java:253)
at org.glassfish.jersey.internal.Errors$1.call(Errors.java:248)
at org.glassfish.jersey.internal.Errors$1.call(Errors.java:244)
at org.glassfish.jersey.internal.Errors.process(Errors.java:292)

2021-08-02 15:05:51.825 [ForkJoinPool.commonPool-worker-27] WARN o.a.p.b.service.persistent.DispatchRateLimiter - Failed to get message-rate for persistent://WiseCloudDMQService/WiseCloudDMQAminService/xsj.testtopic.0730.05-partition-16
java.util.concurrent.TimeoutException: null
at java.util.concurrent.CompletableFuture.timedGet(CompletableFuture.java:1784)
at java.util.concurrent.CompletableFuture.get(CompletableFuture.java:1928)
at org.apache.pulsar.broker.service.persistent.DispatchRateLimiter.getPolicies(DispatchRateLimiter.java:311)
at org.apache.pulsar.broker.service.persistent.SubscribeRateLimiter.getPoliciesSubscribeRate(SubscribeRateLimiter.java:227)
at org.apache.pulsar.broker.service.persistent.SubscribeRateLimiter.getPoliciesSubscribeRate(SubscribeRateLimiter.java:205)
at org.apache.pulsar.broker.service.persistent.SubscribeRateLimiter.onSubscribeRateUpdate(SubscribeRateLimiter.java:167)
at org.apache.pulsar.broker.service.persistent.SubscribeRateLimiter.onPoliciesUpdate(SubscribeRateLimiter.java:162)
at org.apache.pulsar.broker.service.persistent.PersistentTopic.onPoliciesUpdate(PersistentTopic.java:2027)
at org.apache.pulsar.broker.service.BrokerService.lambda$null$62(BrokerService.java:1602)
at java.util.Optional.ifPresent(Optional.java:159)
at org.apache.pulsar.broker.service.BrokerService.lambda$null$63(BrokerService.java:1602)
at java.util.concurrent.CompletableFuture.uniAccept(CompletableFuture.java:670)
at java.util.concurrent.CompletableFuture.uniAcceptStage(CompletableFuture.java:683)
at java.util.concurrent.CompletableFuture.thenAccept(CompletableFuture.java:2010)

trace org.apache.pulsar.broker.service.persistent.DispatchRateLimiter getPolicies

---ts=2021-08-02 15:11:21;thread_name=ForkJoinPool.commonPool-worker-60;id=c47;is_daemon=true;priority=5;TCCL=sun.misc.Launcher$AppClassLoader@18b4aac2 ---[30001.016609ms] org.apache.pulsar.broker.service.persistent.DispatchRateLimiter:getPolicies()
+---[0.003785ms] org.apache.pulsar.common.naming.TopicName:get() #304
+---[0.002569ms] org.apache.pulsar.common.naming.TopicName:getNamespaceObject() #304
+---[0.002541ms] org.apache.pulsar.common.naming.NamespaceName:toString() #305
+---[0.003915ms] org.apache.pulsar.broker.web.PulsarWebResource:path() #305
+---[0.002655ms] org.apache.pulsar.broker.service.BrokerService:pulsar() #308
+---[0.002662ms] org.apache.pulsar.broker.PulsarService:getConfigurationCache() #308
+---[0.003075ms] org.apache.pulsar.broker.cache.ConfigurationCacheService:policiesCache() #310
+---[0.020181ms] org.apache.pulsar.zookeeper.ZooKeeperDataCache:getAsync() #310
+---[0.002184ms] org.apache.pulsar.broker.service.BrokerService:pulsar() #311
+---[0.002972ms] org.apache.pulsar.broker.PulsarService:getConfiguration() #311
`---[0.00194ms] org.apache.pulsar.broker.ServiceConfiguration:getZooKeeperOperationTimeoutSeconds() #311