Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

[fix][metadata] Handle session events in a separate thread #17638

Merged

Conversation

lhotari
Copy link
Member

@lhotari lhotari commented Sep 14, 2022

Motivation

  • session listener might block further processing, and therefore it's better to run it in another thread
  • here's an example of a stacktrace happening in a Bookie with the Pulsar metadata store classes:
metadata-store-zk-session-watcher-21-1  Waiting Thread ID: 60
  jdk.internal.misc.Unsafe.park(Unsafe.java)
  java.util.concurrent.locks.LockSupport.park(LockSupport.java:194)
  java.util.concurrent.CompletableFuture$Signaller.block(CompletableFuture.java:1796)
  java.util.concurrent.ForkJoinPool.managedBlock(ForkJoinPool.java:3128)
  java.util.concurrent.CompletableFuture.waitingGet(CompletableFuture.java:1823)
  java.util.concurrent.CompletableFuture.join(CompletableFuture.java:2043)
  org.apache.pulsar.metadata.coordination.impl.LeaderElectionImpl.close(LeaderElectionImpl.java:233)
  org.apache.pulsar.metadata.bookkeeper.PulsarLedgerAuditorManager.close(PulsarLedgerAuditorManager.java:96)
  org.apache.bookkeeper.replication.AuditorElector.shutdown(AuditorElector.java:234)
  org.apache.bookkeeper.replication.AutoRecoveryMain.shutdown(AutoRecoveryMain.java:154)
  org.apache.bookkeeper.replication.AutoRecoveryMain.lambda$new$0(AutoRecoveryMain.java:99)
  org.apache.bookkeeper.replication.AutoRecoveryMain$$Lambda$222.onSessionExpired()
  org.apache.pulsar.metadata.bookkeeper.PulsarMetadataClientDriver.lambda$setSessionStateListener$0(PulsarMetadataClientDriver.java:68)
  org.apache.pulsar.metadata.bookkeeper.PulsarMetadataClientDriver$$Lambda$223.accept()
  org.apache.pulsar.metadata.impl.AbstractMetadataStore.lambda$receivedSessionEvent$11(AbstractMetadataStore.java:297)
  org.apache.pulsar.metadata.impl.AbstractMetadataStore$$Lambda$342.accept()
  java.util.concurrent.CopyOnWriteArrayList.forEach(CopyOnWriteArrayList.java:807)
  org.apache.pulsar.metadata.impl.AbstractMetadataStore.receivedSessionEvent(AbstractMetadataStore.java:295)
  org.apache.pulsar.metadata.impl.ZKMetadataStore.receivedSessionEvent(ZKMetadataStore.java:152)
  org.apache.pulsar.metadata.impl.ZKMetadataStore$$Lambda$148.accept()
  org.apache.pulsar.metadata.impl.ZKSessionWatcher.checkState(ZKSessionWatcher.java:150)
  org.apache.pulsar.metadata.impl.ZKSessionWatcher.checkConnectionStatus(ZKSessionWatcher.java:110)
  org.apache.pulsar.metadata.impl.ZKSessionWatcher$$Lambda$149.run()
  org.apache.pulsar.common.util.Runnables$CatchingAndLoggingRunnable.run(Runnables.java:54)
  java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
  java.util.concurrent.FutureTask.runAndReset(FutureTask.java:305)
  java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305)
  java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
  java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
  io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
  java.lang.Thread.run(Thread.java:834)

Modifications

  • handle session events in a separate thread

Documentation

  • doc-required
    (Your PR needs to update docs and you will update later)

  • doc-not-needed
    (Please explain why)

  • doc
    (Your PR contains doc changes)

  • doc-complete
    (Docs have been already added)

- session listener might block further processing and therefore it's better to run it in another thread
}
});
try {
executor.execute(() -> {
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

One concern that I have with this patch is that usually in ZooKeeper client applications you leverage the feature that all the events are dispatched in strict order.
Here we are moving the execution of the listeners to another thread, and it actually works as the executor is still single threaded.
But on the other hand.. aren't we moving the problem to the metadata-store ?

maybe the problem is to be fixed in AutoRecoveryMain.... onSessionExpired() that is performing a blocking operation (depending on a sync ZooKeeper calll) on the main zookeeper thread.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Good point. However, in AbstractMetadataStore, the other notifications are delivered using a separate thread pool:

protected CompletableFuture<Void> receivedNotification(Notification notification) {
try {
return CompletableFuture.supplyAsync(() -> {
listeners.forEach(listener -> {
try {
listener.accept(notification);
} catch (Throwable t) {
log.error("Failed to process metadata store notification", t);
}
});
return null;
}, executor);
} catch (RejectedExecutionException e) {
return FutureUtil.failedFuture(e);
}
}

This PR makes AbstractMetadataStore more consistent by also delivering session events using this same thread pool.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I noticed that call as well ;-)

So overall I agree with this patch, because it makes it consistent the way we dispatch the events.

But I am not 100% sure that it will fix the original problem

Copy link
Contributor

@eolivelli eolivelli left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

+1

but we have to fix the problem also in BookKeeper

@eolivelli
Copy link
Contributor

@lhotari @merlimat
BookKeeper fix apache/bookkeeper#3487

Copy link
Contributor

@Jason918 Jason918 left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LGTM

@codelipenghui codelipenghui merged commit 69f3f74 into apache:master Sep 19, 2022
codelipenghui added a commit to codelipenghui/incubator-pulsar that referenced this pull request Sep 30, 2022
### Motivation

[fix][broker] Fix the broker shutdown issue after the Zookeeper node crashed

### Motivation

The broker was shutdown unexpectedly after the Zookeeper node crashed. I have a test to kill the zookeeper node periodically, sometimes the following logs will appear

```
Sep 30 12:21:33 ip-10-0-0-160.us-west-2.compute.internal pulsar[21529]: 2022-09-30T12:21:33,214+0000 [metadata-store-zk-session-watcher-7-1] WARN  org.apache.pulsar.metadata.impl.ZKSessionWatcher - ZooKeeper client is disconnected. Waiting to reconnect, time remaining = 22.245 seconds
Sep 30 12:21:35 ip-10-0-0-160.us-west-2.compute.internal pulsar[21529]: 2022-09-30T12:21:35,214+0000 [metadata-store-zk-session-watcher-7-1] WARN  org.apache.pulsar.metadata.impl.ZKSessionWatcher - ZooKeeper client is disconnected. Waiting to reconnect, time remaining = 20.245 seconds
Sep 30 12:21:37 ip-10-0-0-160.us-west-2.compute.internal pulsar[21529]: 2022-09-30T12:21:37,214+0000 [metadata-store-zk-session-watcher-7-1] WARN  org.apache.pulsar.metadata.impl.ZKSessionWatcher - ZooKeeper client is disconnected. Waiting to reconnect, time remaining = 18.244 seconds
Sep 30 12:21:37 ip-10-0-0-160.us-west-2.compute.internal pulsar[21529]: 2022-09-30T12:21:37,523+0000 [pulsar-web-36-43] INFO  org.eclipse.jetty.server.RequestLog - 10.0.0.54 - - [30/Sep/2022:12:21:37 +0000] "GET /metrics HTTP/1.1" 302 0 "-" "Prometheus/2.31.1" 0
Sep 30 12:21:37 ip-10-0-0-160.us-west-2.compute.internal pulsar[21529]: 2022-09-30T12:21:37,526+0000 [prometheus-stats-37-1] INFO  org.eclipse.jetty.server.RequestLog - 10.0.0.54 - - [30/Sep/2022:12:21:37 +0000] "GET /metrics/ HTTP/1.1" 200 21383 "http://10.0.0.160:8080/metrics" "Prometheus/2.31.1" 2
Sep 30 12:21:39 ip-10-0-0-160.us-west-2.compute.internal pulsar[21529]: 2022-09-30T12:21:39,214+0000 [metadata-store-zk-session-watcher-7-1] WARN  org.apache.pulsar.metadata.impl.ZKSessionWatcher - ZooKeeper client is disconnected. Waiting to reconnect, time remaining = 16.244 seconds
Sep 30 12:21:41 ip-10-0-0-160.us-west-2.compute.internal pulsar[21529]: 2022-09-30T12:21:41,214+0000 [metadata-store-zk-session-watcher-7-1] WARN  org.apache.pulsar.metadata.impl.ZKSessionWatcher - ZooKeeper client is disconnected. Waiting to reconnect, time remaining = 14.244 seconds
Sep 30 12:21:43 ip-10-0-0-160.us-west-2.compute.internal pulsar[21529]: 2022-09-30T12:21:43,215+0000 [metadata-store-zk-session-watcher-7-1] WARN  org.apache.pulsar.metadata.impl.ZKSessionWatcher - ZooKeeper client is disconnected. Waiting to reconnect, time remaining = 12.244 seconds
Sep 30 12:21:45 ip-10-0-0-160.us-west-2.compute.internal pulsar[21529]: 2022-09-30T12:21:45,215+0000 [metadata-store-zk-session-watcher-7-1] WARN  org.apache.pulsar.metadata.impl.ZKSessionWatcher - ZooKeeper client is disconnected. Waiting to reconnect, time remaining = 10.243 seconds
Sep 30 12:21:47 ip-10-0-0-160.us-west-2.compute.internal pulsar[21529]: 2022-09-30T12:21:47,215+0000 [metadata-store-zk-session-watcher-7-1] WARN  org.apache.pulsar.metadata.impl.ZKSessionWatcher - ZooKeeper client is disconnected. Waiting to reconnect, time remaining = 8.243 seconds
Sep 30 12:21:47 ip-10-0-0-160.us-west-2.compute.internal pulsar[21529]: 2022-09-30T12:21:47,523+0000 [pulsar-web-36-43] INFO  org.eclipse.jetty.server.RequestLog - 10.0.0.54 - - [30/Sep/2022:12:21:47 +0000] "GET /metrics HTTP/1.1" 302 0 "-" "Prometheus/2.31.1" 0
Sep 30 12:21:47 ip-10-0-0-160.us-west-2.compute.internal pulsar[21529]: 2022-09-30T12:21:47,526+0000 [prometheus-stats-37-1] INFO  org.eclipse.jetty.server.RequestLog - 10.0.0.54 - - [30/Sep/2022:12:21:47 +0000] "GET /metrics/ HTTP/1.1" 200 21383 "http://10.0.0.160:8080/metrics" "Prometheus/2.31.1" 2
Sep 30 12:21:49 ip-10-0-0-160.us-west-2.compute.internal pulsar[21529]: 2022-09-30T12:21:49,215+0000 [metadata-store-zk-session-watcher-7-1] WARN  org.apache.pulsar.metadata.impl.ZKSessionWatcher - ZooKeeper client is disconnected. Waiting to reconnect, time remaining = 6.243 seconds
Sep 30 12:21:51 ip-10-0-0-160.us-west-2.compute.internal pulsar[21529]: 2022-09-30T12:21:51,216+0000 [metadata-store-zk-session-watcher-7-1] WARN  org.apache.pulsar.metadata.impl.ZKSessionWatcher - ZooKeeper client is disconnected. Waiting to reconnect, time remaining = 4.243 seconds
Sep 30 12:21:53 ip-10-0-0-160.us-west-2.compute.internal pulsar[21529]: 2022-09-30T12:21:53,216+0000 [metadata-store-zk-session-watcher-7-1] WARN  org.apache.pulsar.metadata.impl.ZKSessionWatcher - ZooKeeper client is disconnected. Waiting to reconnect, time remaining = 2.243 seconds
Sep 30 12:21:55 ip-10-0-0-160.us-west-2.compute.internal pulsar[21529]: 2022-09-30T12:21:55,216+0000 [metadata-store-zk-session-watcher-7-1] WARN  org.apache.pulsar.metadata.impl.ZKSessionWatcher - ZooKeeper client is disconnected. Waiting to reconnect, time remaining = 0.242 seconds
Sep 30 12:21:57 ip-10-0-0-160.us-west-2.compute.internal pulsar[21529]: 2022-09-30T12:21:57,216+0000 [metadata-store-zk-session-watcher-7-1] ERROR org.apache.pulsar.metadata.impl.ZKSessionWatcher - ZooKeeper session reconnection timeout. Notifying session is lost.
Sep 30 12:21:57 ip-10-0-0-160.us-west-2.compute.internal pulsar[21529]: 2022-09-30T12:21:57,216+0000 [metadata-store-zk-session-watcher-7-1] INFO  org.apache.pulsar.broker.PulsarService - Received metadata service session event: SessionLost
Sep 30 12:21:57 ip-10-0-0-160.us-west-2.compute.internal pulsar[21529]: 2022-09-30T12:21:57,216+0000 [metadata-store-zk-session-watcher-7-1] WARN  org.apache.pulsar.broker.PulsarService - The session with metadata service was lost. Shutting down.
Sep 30 12:21:57 ip-10-0-0-160.us-west-2.compute.internal pulsar[21529]: 2022-09-30T12:21:57,216+0000 [metadata-store-zk-session-watcher-7-1] INFO  org.apache.pulsar.broker.PulsarService - Invoking Pulsar service immediate shutdown
Sep 30 12:21:57 ip-10-0-0-160.us-west-2.compute.internal pulsar[21529]: 2022-09-30T12:21:57,323+0000 [metadata-store-zk-session-watcher-7-1] INFO  org.apache.zookeeper.ZooKeeper - Session: 0xcc55e0015 closed
Sep 30 12:21:57 ip-10-0-0-160.us-west-2.compute.internal pulsar[21529]: 2022-09-30T12:21:57,324+0000 [metadata-store-zk-session-watcher-7-1] WARN  org.apache.pulsar.broker.PulsarService - Failed to close metadata service session: null
Sep 30 12:21:57 ip-10-0-0-160.us-west-2.compute.internal pulsar[21529]: 2022-09-30T12:21:57,324+0000 [metadata-store-zk-session-watcher-7-1] INFO  org.apache.pulsar.PulsarBrokerStarter - Halting broker process with code -1
```

Then I try to make the thread dump when the broker performing the `Waiting to reconnect`

```
```
"main-EventThread" apache#27 daemon prio=5 os_prio=0 cpu=126.35ms elapsed=1369.57s tid=0x00007f453d65d1a0 nid=0x1c3df waiting for monitor entry  [0x00007f429da8a000]
   java.lang.Thread.State: BLOCKED (on object monitor)
    at org.apache.pulsar.metadata.impl.ZKSessionWatcher.process(ZKSessionWatcher.java:123)
    - waiting to lock <0x0000100007c41a30> (a org.apache.pulsar.metadata.impl.ZKSessionWatcher)
    at org.apache.pulsar.metadata.impl.ZKMetadataStore.lambda$null$0(ZKMetadataStore.java:78)
    at org.apache.pulsar.metadata.impl.ZKMetadataStore$$Lambda$546/0x000000080111e888.accept(Unknown Source)
    at java.util.Optional.ifPresent(java.base@17.0.4.1/Optional.java:178)
    at org.apache.pulsar.metadata.impl.ZKMetadataStore.lambda$new$1(ZKMetadataStore.java:78)
    at org.apache.pulsar.metadata.impl.ZKMetadataStore$$Lambda$124/0x0000000800e29478.process(Unknown Source)
    at org.apache.bookkeeper.zookeeper.ZooKeeperWatcherBase.notifyEvent(ZooKeeperWatcherBase.java:180)
    at org.apache.bookkeeper.zookeeper.ZooKeeperWatcherBase.process(ZooKeeperWatcherBase.java:146)
    at org.apache.zookeeper.ClientCnxn$EventThread.processEvent(ClientCnxn.java:588)
    at org.apache.zookeeper.ClientCnxn$EventThread.run(ClientCnxn.java:563)

   Locked ownable synchronizers:
    - None

"metadata-store-zk-session-watcher-7-1" apache#28 prio=5 os_prio=0 cpu=36.92ms elapsed=1369.54s tid=0x00007f453d665b60 nid=0x1c3e0 waiting on condition  [0x00007f429d786000]
   java.lang.Thread.State: TIMED_WAITING (parking)
    at jdk.internal.misc.Unsafe.park(java.base@17.0.4.1/Native Method)
    - parking to wait for  <0x0000100029e10418> (a java.util.concurrent.CompletableFuture$Signaller)
    at java.util.concurrent.locks.LockSupport.parkNanos(java.base@17.0.4.1/LockSupport.java:252)
    at java.util.concurrent.CompletableFuture$Signaller.block(java.base@17.0.4.1/CompletableFuture.java:1866)
    at java.util.concurrent.ForkJoinPool.unmanagedBlock(java.base@17.0.4.1/ForkJoinPool.java:3463)
    at java.util.concurrent.ForkJoinPool.managedBlock(java.base@17.0.4.1/ForkJoinPool.java:3434)
    at java.util.concurrent.CompletableFuture.timedGet(java.base@17.0.4.1/CompletableFuture.java:1939)
    at java.util.concurrent.CompletableFuture.get(java.base@17.0.4.1/CompletableFuture.java:2095)
    at org.apache.pulsar.metadata.impl.ZKSessionWatcher.checkConnectionStatus(ZKSessionWatcher.java:107)
    - locked <0x0000100007c41a30> (a org.apache.pulsar.metadata.impl.ZKSessionWatcher)
    at org.apache.pulsar.metadata.impl.ZKSessionWatcher$$Lambda$129/0x0000000800e36598.run(Unknown Source)
    at org.apache.pulsar.common.util.Runnables$CatchingAndLoggingRunnable.run(Runnables.java:53)
    at java.util.concurrent.Executors$RunnableAdapter.call(java.base@17.0.4.1/Executors.java:539)
    at java.util.concurrent.FutureTask.runAndReset(java.base@17.0.4.1/FutureTask.java:305)
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(java.base@17.0.4.1/ScheduledThreadPoolExecutor.java:305)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@17.0.4.1/ThreadPoolExecutor.java:1136)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@17.0.4.1/ThreadPoolExecutor.java:635)
    at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
    at java.lang.Thread.run(java.base@17.0.4.1/Unknown Source)
```

It's a deadlock issue happened on the broker side.

### Modification

As apache#17638, process the session event in separated thread to avoid the deadlock

### Verification

The test continues running 6 hours, I don't see the issue happens again. Without this fix, the problem will happen in 10 min during the
test.
dlg99 pushed a commit to dlg99/pulsar that referenced this pull request Oct 3, 2022
nicoloboschi pushed a commit to datastax/pulsar that referenced this pull request Oct 4, 2022
gaozhangmin pushed a commit to gaozhangmin/pulsar that referenced this pull request Apr 6, 2023
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
area/metadata doc-not-needed Your PR changes do not impact docs
Projects
None yet
Development

Successfully merging this pull request may close these issues.

4 participants