Broker gets stuck when getting partitioned stats

[nkurihar]

Describe the bug

Brokers in our cluster get stuck when executing internalGetPartitionedStats:

pulsar/pulsar-broker/src/main/java/org/apache/pulsar/broker/admin/impl/PersistentTopicsBase.java

Lines 609 to 610 in 3cfa812

	TopicStats partitionStats = pulsar().getAdminClient().topics()
	.getStats(topicName.getPartition(i).toString());

thread dump:
https://gist.github.com/nkurihar/5d90ce683802390cdec2d9fb65cc0297

"pulsar-web-28-32" #531 prio=5 os_prio=0 tid=0x00007f31a4001000 nid=0x3b69 waiting on condition [0x00007f30db1c6000]
   java.lang.Thread.State: WAITING (parking)
	at sun.misc.Unsafe.park(Native Method)
	- parking to wait for  <0x00007f512c8e2d80> (a java.util.concurrent.CompletableFuture$Signaller)
	at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
	at java.util.concurrent.CompletableFuture$Signaller.block(CompletableFuture.java:1693)
	at java.util.concurrent.ForkJoinPool.managedBlock(ForkJoinPool.java:3323)
	at java.util.concurrent.CompletableFuture.waitingGet(CompletableFuture.java:1729)
	at java.util.concurrent.CompletableFuture.get(CompletableFuture.java:1895)
	at org.apache.pulsar.client.admin.internal.TopicsImpl.getStats(TopicsImpl.java:380)
	at org.apache.pulsar.broker.admin.impl.PersistentTopicsBase.internalGetPartitionedStats(PersistentTopicsBase.java:610)
	at org.apache.pulsar.broker.admin.v1.PersistentTopics.getPartitionedStats(PersistentTopics.java:279)
	at sun.reflect.GeneratedMethodAccessor56.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$1.invoke(ResourceMethodInvocationHandlerFactory.java:81)
	at org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher$1.run(AbstractJavaResourceMethodDispatcher.java:144)
	at org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher.invoke(AbstractJavaResourceMethodDispatcher.java:161)
	at org.glassfish.jersey.server.model.internal.JavaResourceMethodDispatcherProvider$TypeOutInvoker.doDispatch(JavaResourceMethodDispatcherProvider.java:205)
	at org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher.dispatch(AbstractJavaResourceMethodDispatcher.java:99)
	at org.glassfish.jersey.server.model.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:389)
	at org.glassfish.jersey.server.model.ResourceMethodInvoker.apply(ResourceMethodInvoker.java:347)
	at org.glassfish.jersey.server.model.ResourceMethodInvoker.apply(ResourceMethodInvoker.java:102)
	at org.glassfish.jersey.server.ServerRuntime$2.run(ServerRuntime.java:326)
	at org.glassfish.jersey.internal.Errors$1.call(Errors.java:271)
	at org.glassfish.jersey.internal.Errors$1.call(Errors.java:267)
	at org.glassfish.jersey.internal.Errors.process(Errors.java:315)
	at org.glassfish.jersey.internal.Errors.process(Errors.java:297)
	at org.glassfish.jersey.internal.Errors.process(Errors.java:267)
	at org.glassfish.jersey.process.internal.RequestScope.runInScope(RequestScope.java:317)
	at org.glassfish.jersey.server.ServerRuntime.process(ServerRuntime.java:305)
	at org.glassfish.jersey.server.ApplicationHandler.handle(ApplicationHandler.java:1154)
	at org.glassfish.jersey.servlet.WebComponent.serviceImpl(WebComponent.java:473)
	at org.glassfish.jersey.servlet.WebComponent.service(WebComponent.java:427)
	at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:388)
	at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:341)
	at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:228)
	at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:845)
	at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1689)
	at org.apache.pulsar.broker.web.ResponseHandlerFilter.doFilter(ResponseHandlerFilter.java:53)
	at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1676)
	at org.apache.pulsar.broker.web.AuthenticationFilter.doFilter(AuthenticationFilter.java:74)
	at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1676)
	at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:581)
	at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:224)
	at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1180)
	at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:511)
	at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:185)
	at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1112)
	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)
	at org.eclipse.jetty.server.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:213)
	at org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:119)
	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:134)
	at org.eclipse.jetty.server.Server.handle(Server.java:524)
	at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:319)
	at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:253)
	at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:273)
	at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:95)
	at org.eclipse.jetty.io.ssl.SslConnection.onFillable(SslConnection.java:202)
	at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:273)
	at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:95)
	at org.eclipse.jetty.io.SelectChannelEndPoint$2.run(SelectChannelEndPoint.java:93)
	at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.executeProduceConsume(ExecuteProduceConsume.java:303)
	at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.produceConsume(ExecuteProduceConsume.java:148)
	at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.run(ExecuteProduceConsume.java:136)
	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)

To Reproduce
We haven't found the way to reproduce yet.

Additional context
Broker OS: CentOS Linux release 7.6.1810
Broker version: 2.2.1
Broker spec: Real server / 2.10GHz / 2CPU / 256GBMEM / SATA SSD 240GB x1 / 10G Base-T*2port

[k2la]

To Reproduce

Execute following command:

$ seq 1 100 | xargs -I ZZ -P 100 curl -LI dev-broker.pulsar.co.jp:4080/admin/persistent/tenant/global/ns/partitioned-topic10/partitioned-stats -o /dev/null -w '%{http_code}\n' -s

[nkurihar]

It seems that all pulsar-web threads are trying to execute getPartitionedStats, however there are no more "free" threads which can respond topic stats for partitions (<topicname>-partition-0, <topicname>-partition-1, <topicname>-partition-2, ...)

[rdhabalia]

@nkurihar do you see any exception in the log specially related to async-zk-cache?

[rdhabalia]

@nkurihar i think #4484 will help to avoid deadlock in broker.

[merlimat]

While #4484 is fine, I think we should rather use the async REST handler for this operation

[rdhabalia]

I think we should rather use the async REST handler for this operation

I don't think that will help much because broker is not using async servlet and web-thread has to wait till it receives all the async responses for all partitions. so, in that case also, broker has to add timeout on the blocking call to avoid deadlock.

[merlimat]

We can use async handler for the partitioned topics stats. That will not block the Jetty thread in the first place

[nkurihar]

@rdhabalia @merlimat
Thank you for your help!

do you see any exception in the log specially related to async-zk-cache?

No, I don't see exceptions related to async-zk-cache.

[rdhabalia]

We can use async handler for the partitioned topics stats

yes..let me make the change.

[rdhabalia]

@merlimat @nkurihar created #4487

[nkurihar]

@rdhabalia
We internally patched your 2 PRs and found that the issue no longer occurs.
Thank your for your great job!