I've searched, but couldn't find. Is there some kn...
# general
g
I've searched, but couldn't find. Is there some known issue in 2.10.4 or above (we moved from 2.10.3 to 2.10.5) where the broker hangs in a way that new bundles get moved to the broker but the broker doesn't realise it. So send calls fail as connection can't be formed with the broker. Logs don't seem to help much and so far not much luck in analysing heap or thread dump
l
"get moved to the broker but the broker doesn't realise it" . Would you be able to explain more about this hypothesis? btw. Eclipse MAT + Calcite plugin is sometimes very useful in analysis since you can write SQL queries to summarize information from the heap dump.
👍 1
a
Brilliant . Didn’t know that about calcite plugin
l
on Mac Apple Silicon, I have to do
open /Applications/MemoryAnalyzer.app
to start MAT. The max heap size should be adjusted from -Xmx1024m to -Xmx4g by editing
/Applications/MemoryAnalyzer.app/Contents/Eclipse/MemoryAnalyzer.ini
.
Here's a real world example of some test OOME debugging: https://github.com/apache/pulsar/pull/22586#issuecomment-2077871792
some other Eclipse MAT + Calcite example in the context of Pulsar:
Copy code
-- the amount of http server connections
select _connections from org.eclipse.jetty.server.ConnectionLimit

-- http request uris (a lot seem to have empty uri)
select _originalURI from org.eclipse.jetty.server.Request

-- connected Pulsar binary protocol clients and counts
select clientVersion, count(clientVersion) from org.apache.pulsar.broker.service.ServerCnx group by 1 order by 2 desc
😮 2
g
Btw, the dumps are normal. The memory and cpu usage is normal as well
The hypothesis - in a rollout the last restarted (ordinal 0 in k8s sts) broker has 0 bundles. Other brokers aren't shedding either, so that broker remains at 0. But suppose now another broker restarts, it's bundles gets moved to least used broker, so the 0th broker.
But sometimes, this 0th broker's topic count doesn't increase, not does it starts accepting requests, while the clients see send timeouts
Even doing any lookup on the broker locally fails with a timeout
l
it's too bad it in such state that logs don't reveal much. I think a heap dump and thread dumps will be the best way to make progress unless you are able to reproduce in an environment where it's fine to debug. In a heap dump, there could be multiple ways to slice&dice the information. I usually use Yourkit Java Profiler and Eclipse MAT + Calcite to do that. Today I found out that checking for
CompletableFuture
instances could be a good way to investigate async issues. For some reason Pulsar master branch is in a bad state where a lot of tests fail with OOMEs.
select * from java.util.concurrent.CompletableFuture
is one possible starting point for checking what CompletableFutures are outstanding.
m
@Lari Hotari We tried analysing the thread dump and found one of the thread of managed ledger is getting blocked by metadata store
Copy code
"metadata-store-10-1" #19 prio=5 os_prio=0 cpu=50535.64ms elapsed=25032.74s tid=0x00007f22417f96a0 nid=0xe2 waiting for monitor entry  [0x00007f1fba8e4000]
   java.lang.Thread.State: BLOCKED (on object monitor)
	at java.util.concurrent.ConcurrentHashMap.computeIfAbsent(java.base@17.0.10/ConcurrentHashMap.java:1726)
	- waiting to lock <0x00001000c0882098> (a java.util.concurrent.ConcurrentHashMap$ReservationNode)
	at org.apache.pulsar.broker.ManagedLedgerClientFactory.lambda$initialize$1(ManagedLedgerClientFactory.java:93)
	at org.apache.pulsar.broker.ManagedLedgerClientFactory$$Lambda$243/0x00007f1fbc329e28.get(Unknown Source)
	at org.apache.bookkeeper.mledger.impl.ManagedLedgerFactoryImpl.lambda$asyncOpen$6(ManagedLedgerFactoryImpl.java:369)
	at org.apache.bookkeeper.mledger.impl.ManagedLedgerFactoryImpl$$Lambda$1203/0x00007f1fbc8ce498.apply(Unknown Source)
	at java.util.concurrent.ConcurrentHashMap.computeIfAbsent(java.base@17.0.10/ConcurrentHashMap.java:1708)
	- locked <0x000010010ce8e538> (a java.util.concurrent.ConcurrentHashMap$ReservationNode)
	at org.apache.bookkeeper.mledger.impl.ManagedLedgerFactoryImpl.asyncOpen(ManagedLedgerFactoryImpl.java:365)
	at org.apache.pulsar.broker.service.BrokerService.lambda$createPersistentTopic$65(BrokerService.java:1530)
	at org.apache.pulsar.broker.service.BrokerService$$Lambda$1189/0x00007f1fbc8c78d8.accept(Unknown Source)
	at java.util.concurrent.CompletableFuture$UniAccept.tryFire(java.base@17.0.10/CompletableFuture.java:718)
	at java.util.concurrent.CompletableFuture.postComplete(java.base@17.0.10/CompletableFuture.java:510)
	at java.util.concurrent.CompletableFuture.complete(java.base@17.0.10/CompletableFuture.java:2147)
	at org.apache.pulsar.metadata.impl.ZKMetadataStore.handleGetResult(ZKMetadataStore.java:262)
	at org.apache.pulsar.metadata.impl.ZKMetadataStore.lambda$null$7(ZKMetadataStore.java:206)
	at org.apache.pulsar.metadata.impl.ZKMetadataStore$$Lambda$211/0x00007f1fbc2d7240.run(Unknown Source)
	at java.util.concurrent.Executors$RunnableAdapter.call(java.base@17.0.10/Executors.java:539)
	at java.util.concurrent.FutureTask.run(java.base@17.0.10/FutureTask.java:264)
Also, found the supporting logs where it failed to open the ledger -
Copy code
public void openLedgerFailed(ManagedLedgerException exception, Object ctx) {
                            if (!createIfMissing && exception instanceof ManagedLedgerNotFoundException) {
                                // We were just trying to load a topic and the topic doesn't exist
                                topicFuture.complete(Optional.empty());
                            } else {
                                log.warn("Failed to create topic {}", topic, exception);
                                pulsar.getExecutor().execute(() -> topics.remove(topic, topicFuture));
                                topicFuture.completeExceptionally(new PersistenceException(exception));
                            }
                        }
is there any known issue related to this in 2.10.4 or greater versions?? that it is not releasing the lock while opening a ledger and stucks there. also, adding thread dump here for reference.
👍 1
l
@Manmeet @Girish Sharma it seems that it's a similar problem as https://github.com/apache/pulsar/pull/21096 , but in a different code location. Would you be able to report an issue to https://github.com/apache/pulsar/issues ? thanks
The deadlock issue might be caused by https://github.com/apache/pulsar/pull/18672 .
It must be a different problem. The thread dump was very useful. the line numbers seemed to match 2.10.6 . One possible way to solve the problem would be to change
thenAccept
on this line https://github.com/apache/pulsar/blob/c1d8630b13e782935def3c4b12b59ae9aa8e5541/pul[…]c/main/java/org/apache/pulsar/broker/service/BrokerService.java to
thenAcceptAsync
. That would prevent the metadata store getting blocked and essentially dead locked.
g
Thanks for looking into this . We will check these out. We also tried a lot to reproduce it in lower environment but to no avail. Moreover, it seems to happen more often right after a rollout for next few days.... And settles a bit post that
l
it seems that the same bug is also in the master branch so it will be useful to report it. The thread dump was super useful in getting an understanding of the problem. https://jstack.review was useful in analysing the thread dump. I usually upload thread dumps to github gists. and then prepend
<https://jstack.review>?
to the gist url. it magically opens the thread dump in the UI. for example, https://jstack.review/?https://gist.github.com/lhotari/0df79a7a3aab42620ea41cfdaf0c8b2a#tda_1_dump .
gh gist create <filename>
is a convenient way to create gists. ``````