You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@pulsar.apache.org by GitBox <gi...@apache.org> on 2022/10/31 11:27:03 UTC
[GitHub] [pulsar] Shawyeok opened a new issue, #18269: [Bug] zk EventThread get block after zk leader stop
Shawyeok opened a new issue, #18269:
URL: https://github.com/apache/pulsar/issues/18269
### Search before asking
- [X] I searched in the [issues](https://github.com/apache/pulsar/issues) and found nothing similar.
### Version
```shell
# pulsar version: 2.8.1
# cat /etc/redhat-release
CentOS Linux release 7.9.2009 (Core)
# java -version
java version "1.8.0_121"
Java(TM) SE Runtime Environment (build 1.8.0_121-b13)
Java HotSpot(TM) 64-Bit Server VM (build 25.121-b13, mixed mode)
# uname -r
3.10.0-123.el7.x86_64
```
### Minimal reproduce step
Setup a pulsar cluster and zk cluster, could get a chance to reproduce (not always) after stop zk leader
### What did you expect to see?
zk client should reconnect another zk node properly,
### What did you see instead?
`main-EventThread` is blocking on `org.apache.pulsar.metadata.impl.ZKSessionWatcher#process` method.
```java
"metadata-store-zk-session-watcher-7-1" #16 prio=5 os_prio=0 tid=0x00007fd7ca112000 nid=0x6991 waiting on condition [0x00007fd742afa000]
java.lang.Thread.State: TIMED_WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x00000007953debd8> (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:1695)
at java.util.concurrent.ForkJoinPool.managedBlock(ForkJoinPool.java:3323)
at java.util.concurrent.CompletableFuture.timedGet(CompletableFuture.java:1775)
at java.util.concurrent.CompletableFuture.get(CompletableFuture.java:1915)
at org.apache.pulsar.metadata.impl.ZKSessionWatcher.checkConnectionStatus(ZKSessionWatcher.java:104)
- locked <0x00000006c66130e0> (a org.apache.pulsar.metadata.impl.ZKSessionWatcher)
at org.apache.pulsar.metadata.impl.ZKSessionWatcher$$Lambda$38/909132503.run(Unknown Source)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294)
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)
"main-EventThread" #15 daemon prio=5 os_prio=0 tid=0x00007fd7ca108800 nid=0x6990 waiting for monitor entry [0x00007fd768380000]
java.lang.Thread.State: BLOCKED (on object monitor)
at org.apache.pulsar.metadata.impl.ZKSessionWatcher.process(ZKSessionWatcher.java:120)
- waiting to lock <0x00000006c66130e0> (a org.apache.pulsar.metadata.impl.ZKSessionWatcher)
at org.apache.pulsar.metadata.impl.ZKMetadataStore.lambda$new$0(ZKMetadataStore.java:75)
at org.apache.pulsar.metadata.impl.ZKMetadataStore$$Lambda$35/1305486145.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)
```
`main-EventThread` log:
<img width="1325" alt="image" src="https://user-images.githubusercontent.com/5058708/198993764-10cb9a13-db90-43b8-a709-d8d9d3e6687d.png">
`metadata-store-zk-session-watcher-7-1` log:
<img width="1323" alt="image" src="https://user-images.githubusercontent.com/5058708/198994044-4bb721d4-58f9-452e-abb6-6a1b524e0a25.png">
`org.apache.pulsar.metadata.impl.ZKSessionWatcher#currentStatus` is `SessionLost`
<img width="836" alt="image" src="https://user-images.githubusercontent.com/5058708/198994498-80b3f49e-a615-40b4-b14d-273a56cef366.png">
zk EventThread internal task queue `waitingEvents` has many events to process
<img width="1307" alt="image" src="https://user-images.githubusercontent.com/5058708/198994634-1c6d700b-0aa5-42bf-8990-cb37c892239d.png">
The keeperState of current event that zk EventThread processing is `SyncConnected`
<img width="1388" alt="image" src="https://user-images.githubusercontent.com/5058708/198995351-8bf5ad06-cea2-46fc-9065-ec8068e983fb.png">
It seems that zk exists operation will always timeout cause zk EventThread is blocking and `metadata-store-zk-session-watcher` thread can always acquire lock (I don't understand why, a jvm bug?).
https://github.com/apache/pulsar/blob/0866c3a6a734b39402a6bc8349bab13edab00488/pulsar-metadata/src/main/java/org/apache/pulsar/metadata/impl/ZKSessionWatcher.java#L68-L71
https://github.com/apache/pulsar/blob/0866c3a6a734b39402a6bc8349bab13edab00488/pulsar-metadata/src/main/java/org/apache/pulsar/metadata/impl/ZKSessionWatcher.java#L86-L108
### Anything else?
_No response_
### Are you willing to submit a PR?
- [X] I'm willing to submit a PR!
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@pulsar.apache.org.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [pulsar] Shawyeok commented on issue #18269: [Bug] zk EventThread get block after zk leader stop
Posted by GitBox <gi...@apache.org>.
Shawyeok commented on issue #18269:
URL: https://github.com/apache/pulsar/issues/18269#issuecomment-1297157613
> I think this bug should be resolved at #17909 also.
>
> It seems that the reported version is 2.8.1, while the fix is picked to only after 2.9.x. @codelipenghui do we have a released version including the fix that @Shawyeok can try to use?
I've talked with @codelipenghui, I'll pick that PR into our release branch in my org.
Thanks again for point this out @codelipenghui @tisonkun, I'm going close this one.
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@pulsar.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [pulsar] Shawyeok closed issue #18269: [Bug] zk EventThread get block after zk leader stop
Posted by GitBox <gi...@apache.org>.
Shawyeok closed issue #18269: [Bug] zk EventThread get block after zk leader stop
URL: https://github.com/apache/pulsar/issues/18269
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@pulsar.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [pulsar] Shawyeok commented on issue #18269: [Bug] zk EventThread get block after zk leader stop
Posted by GitBox <gi...@apache.org>.
Shawyeok commented on issue #18269:
URL: https://github.com/apache/pulsar/issues/18269#issuecomment-1296956529
Similar with https://github.com/apache/pulsar/issues/16712
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@pulsar.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [pulsar] tisonkun commented on issue #18269: [Bug] zk EventThread get block after zk leader stop
Posted by GitBox <gi...@apache.org>.
tisonkun commented on issue #18269:
URL: https://github.com/apache/pulsar/issues/18269#issuecomment-1297150269
I think this bug should be resolved at https://github.com/apache/pulsar/pull/17909 also.
It seems that the reported version is 2.8.1. @codelipenghui do we have a released version including the fix that @Shawyeok can try to use?
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@pulsar.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [pulsar] Shawyeok commented on issue #18269: [Bug] zk EventThread get block after zk leader stop
Posted by GitBox <gi...@apache.org>.
Shawyeok commented on issue #18269:
URL: https://github.com/apache/pulsar/issues/18269#issuecomment-1297145269
Update:
> `metadata-store-zk-session-watcher` thread can always acquire lock (I don't understand why, a jvm bug?)
`synchronized` lock is unfair, a thread has big chance acquire lock if it just release it, see example below:
```java
class Scratch {
private static final CountDownLatch latch = new CountDownLatch(1);
public static void main(String[] args) throws InterruptedException {
ScheduledExecutorService scheduler = Executors.newSingleThreadScheduledExecutor();
Scratch s = new Scratch();
scheduler.scheduleAtFixedRate(s::checkState, 2, 2, TimeUnit.SECONDS);
latch.await();
while (true) {
s.process();
}
}
private void process() {
checkState();
}
private synchronized void checkState() {
System.out.println(Thread.currentThread().getName() + " checking state");
if (latch.getCount() > 0) {
latch.countDown();
}
CompletableFuture<Void> future = new CompletableFuture<>();
try {
future.get(2, TimeUnit.SECONDS);
} catch (TimeoutException ignore) {
} catch (Exception e) {
e.printStackTrace();
}
System.out.println(Thread.currentThread().getName() + " finished");
}
}
```
Output:
```
pool-1-thread-1 checking state
pool-1-thread-1 finished
main checking state
main finished
main checking state
main finished
main checking state
main finished
main checking state
main finished
main checking state
main finished
main checking state
main finished
main checking state
main finished
main checking state
main finished
main checking state
main finished
main checking state
main finished
main checking state
main finished
main checking state
main finished
main checking state
main finished
main checking state
main finished
main checking state
main finished
main checking state
main finished
main checking state
main finished
main checking state
main finished
main checking state
main finished
main checking state
main finished
...
```
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@pulsar.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [pulsar] codelipenghui commented on issue #18269: [Bug] zk EventThread get block after zk leader stop
Posted by GitBox <gi...@apache.org>.
codelipenghui commented on issue #18269:
URL: https://github.com/apache/pulsar/issues/18269#issuecomment-1296987982
@Shawyeok The issue should be fixed by #17909
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@pulsar.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org