mattisonchao commented on PR #17237:
URL: https://github.com/apache/pulsar/pull/17237#issuecomment-1224189584
```
2022-08-23T22:44:06,869+0800 [broker-topic-workers-OrderedExecutor-4-0] INFO
org.apache.pulsar.broker.service.persistent.PersistentDispatcherSingleActiveConsumer
- dispatch message ledger:3 entry:0
2022-08-23T22:44:06,869+0800 [broker-topic-workers-OrderedExecutor-4-0] INFO
org.apache.pulsar.broker.service.persistent.PersistentDispatcherSingleActiveConsumer
- ============= Dispatcher complete ===========
2022-08-23T22:44:06,882+0800 [broker-topic-workers-OrderedExecutor-4-0] INFO
org.apache.pulsar.broker.service.persistent.PersistentDispatcherSingleActiveConsumer
- dispatch message ledger:3 entry:1
2022-08-23T22:44:06,882+0800 [broker-topic-workers-OrderedExecutor-4-0] INFO
org.apache.pulsar.broker.service.persistent.PersistentDispatcherSingleActiveConsumer
- dispatch message ledger:3 entry:2
2022-08-23T22:44:06,882+0800 [broker-topic-workers-OrderedExecutor-4-0] INFO
org.apache.pulsar.broker.service.persistent.PersistentDispatcherSingleActiveConsumer
- dispatch message ledger:3 entry:3
2022-08-23T22:44:06,882+0800 [broker-topic-workers-OrderedExecutor-4-0] INFO
org.apache.pulsar.broker.service.persistent.PersistentDispatcherSingleActiveConsumer
- dispatch message ledger:3 entry:4
2022-08-23T22:44:06,882+0800 [broker-topic-workers-OrderedExecutor-4-0] INFO
org.apache.pulsar.broker.service.persistent.PersistentDispatcherSingleActiveConsumer
- dispatch message ledger:3 entry:5
2022-08-23T22:44:06,882+0800 [broker-topic-workers-OrderedExecutor-4-0] INFO
org.apache.pulsar.broker.service.persistent.PersistentDispatcherSingleActiveConsumer
- dispatch message ledger:3 entry:6
2022-08-23T22:44:06,882+0800 [broker-topic-workers-OrderedExecutor-4-0] INFO
org.apache.pulsar.broker.service.persistent.PersistentDispatcherSingleActiveConsumer
- ============= Dispatcher complete ===========
2022-08-23T22:44:06,883+0800 [broker-topic-workers-OrderedExecutor-4-0] INFO
org.apache.pulsar.broker.service.persistent.PersistentDispatcherSingleActiveConsumer
- dispatch message ledger:3 entry:7
2022-08-23T22:44:06,883+0800 [broker-topic-workers-OrderedExecutor-4-0] INFO
org.apache.pulsar.broker.service.persistent.PersistentDispatcherSingleActiveConsumer
- ============= Dispatcher complete ===========
2022-08-23T22:44:07,884+0800 [pulsar-io-766-3] INFO
org.apache.pulsar.broker.service.persistent.PersistentDispatcherSingleActiveConsumer
- ============= reScheduleRead ===========
2022-08-23T22:44:07,885+0800 [broker-topic-workers-OrderedExecutor-4-0] INFO
org.apache.pulsar.broker.service.persistent.PersistentDispatcherSingleActiveConsumer
- dispatch message ledger:3 entry:8
2022-08-23T22:44:07,885+0800 [broker-topic-workers-OrderedExecutor-4-0] INFO
org.apache.pulsar.broker.service.persistent.PersistentDispatcherSingleActiveConsumer
- dispatch message ledger:3 entry:9
2022-08-23T22:44:07,885+0800 [broker-topic-workers-OrderedExecutor-4-0] INFO
org.apache.pulsar.broker.service.persistent.PersistentDispatcherSingleActiveConsumer
- dispatch message ledger:3 entry:10
2022-08-23T22:44:07,885+0800 [broker-topic-workers-OrderedExecutor-4-0] INFO
org.apache.pulsar.broker.service.persistent.PersistentDispatcherSingleActiveConsumer
- dispatch message ledger:3 entry:11
2022-08-23T22:44:07,885+0800 [broker-topic-workers-OrderedExecutor-4-0] INFO
org.apache.pulsar.broker.service.persistent.PersistentDispatcherSingleActiveConsumer
- dispatch message ledger:3 entry:12
2022-08-23T22:44:07,885+0800 [broker-topic-workers-OrderedExecutor-4-0] INFO
org.apache.pulsar.broker.service.persistent.PersistentDispatcherSingleActiveConsumer
- dispatch message ledger:3 entry:13
2022-08-23T22:44:07,885+0800 [broker-topic-workers-OrderedExecutor-4-0] INFO
org.apache.pulsar.broker.service.persistent.PersistentDispatcherSingleActiveConsumer
- ============= Dispatcher complete ===========
2022-08-23T22:44:07,886+0800 [broker-topic-workers-OrderedExecutor-4-0] INFO
org.apache.pulsar.broker.service.persistent.PersistentDispatcherSingleActiveConsumer
- dispatch message ledger:3 entry:14
2022-08-23T22:44:07,886+0800 [broker-topic-workers-OrderedExecutor-4-0] INFO
org.apache.pulsar.broker.service.persistent.PersistentDispatcherSingleActiveConsumer
- ============= Dispatcher complete ===========
2022-08-23T22:44:07,886+0800 [broker-topic-workers-OrderedExecutor-4-0] INFO
org.apache.pulsar.broker.service.persistent.PersistentDispatcherSingleActiveConsumer
- ============= internalConsumerFlow ===========
2022-08-23T22:44:07,886+0800 [broker-topic-workers-OrderedExecutor-4-0] INFO
org.apache.pulsar.broker.service.persistent.PersistentDispatcherSingleActiveConsumer
- ============= internalConsumerFlow ===========
2022-08-23T22:44:08,887+0800 [pulsar-io-766-5] INFO
org.apache.pulsar.broker.service.persistent.PersistentDispatcherSingleActiveConsumer
- ============= reScheduleRead ===========
2022-08-23T22:44:08,887+0800 [pulsar-io-766-4] INFO
org.apache.pulsar.broker.service.persistent.PersistentDispatcherSingleActiveConsumer
- ============= reScheduleRead ===========
2022-08-23T22:44:08,888+0800 [broker-topic-workers-OrderedExecutor-4-0] INFO
org.apache.pulsar.broker.service.persistent.PersistentDispatcherSingleActiveConsumer
- dispatch message ledger:3 entry:15
2022-08-23T22:44:08,888+0800 [broker-topic-workers-OrderedExecutor-4-0] INFO
org.apache.pulsar.broker.service.persistent.PersistentDispatcherSingleActiveConsumer
- dispatch message ledger:3 entry:16
2022-08-23T22:44:08,888+0800 [broker-topic-workers-OrderedExecutor-4-0] INFO
org.apache.pulsar.broker.service.persistent.PersistentDispatcherSingleActiveConsumer
- dispatch message ledger:3 entry:17
2022-08-23T22:44:08,888+0800 [broker-topic-workers-OrderedExecutor-4-0] INFO
org.apache.pulsar.broker.service.persistent.PersistentDispatcherSingleActiveConsumer
- dispatch message ledger:3 entry:18
2022-08-23T22:44:08,888+0800 [broker-topic-workers-OrderedExecutor-4-0] INFO
org.apache.pulsar.broker.service.persistent.PersistentDispatcherSingleActiveConsumer
- dispatch message ledger:3 entry:19
2022-08-23T22:44:08,888+0800 [broker-topic-workers-OrderedExecutor-4-0] INFO
org.apache.pulsar.broker.service.persistent.PersistentDispatcherSingleActiveConsumer
- dispatch message ledger:3 entry:20
2022-08-23T22:44:08,888+0800 [broker-topic-workers-OrderedExecutor-4-0] INFO
org.apache.pulsar.broker.service.persistent.PersistentDispatcherSingleActiveConsumer
- dispatch message ledger:3 entry:15
2022-08-23T22:44:08,888+0800 [broker-topic-workers-OrderedExecutor-4-0] INFO
org.apache.pulsar.broker.service.persistent.PersistentDispatcherSingleActiveConsumer
- dispatch message ledger:3 entry:16
2022-08-23T22:44:08,888+0800 [broker-topic-workers-OrderedExecutor-4-0] INFO
org.apache.pulsar.broker.service.persistent.PersistentDispatcherSingleActiveConsumer
- dispatch message ledger:3 entry:17
2022-08-23T22:44:08,888+0800 [broker-topic-workers-OrderedExecutor-4-0] INFO
org.apache.pulsar.broker.service.persistent.PersistentDispatcherSingleActiveConsumer
- dispatch message ledger:3 entry:18
2022-08-23T22:44:08,888+0800 [broker-topic-workers-OrderedExecutor-4-0] INFO
org.apache.pulsar.broker.service.persistent.PersistentDispatcherSingleActiveConsumer
- dispatch message ledger:3 entry:19
2022-08-23T22:44:08,888+0800 [broker-topic-workers-OrderedExecutor-4-0] INFO
org.apache.pulsar.broker.service.persistent.PersistentDispatcherSingleActiveConsumer
- dispatch message ledger:3 entry:20
2022-08-23T22:44:08,888+0800 [broker-topic-workers-OrderedExecutor-4-0] INFO
org.apache.pulsar.broker.service.persistent.PersistentDispatcherSingleActiveConsumer
- ============= Dispatcher complete ===========
2022-08-23T22:44:08,889+0800 [broker-topic-workers-OrderedExecutor-4-0] INFO
org.apache.pulsar.broker.service.persistent.PersistentDispatcherSingleActiveConsumer
- ============= Dispatcher complete ===========
2022-08-23T22:44:08,889+0800 [broker-topic-workers-OrderedExecutor-4-0] INFO
org.apache.pulsar.broker.service.persistent.PersistentDispatcherSingleActiveConsumer
- ============= internalConsumerFlow ===========
2022-08-23T22:44:08,889+0800 [broker-topic-workers-OrderedExecutor-4-0] INFO
org.apache.pulsar.broker.service.persistent.PersistentDispatcherSingleActiveConsumer
- ============= internalConsumerFlow ===========
2022-08-23T22:44:09,890+0800 [pulsar-io-766-6] INFO
org.apache.pulsar.broker.service.persistent.PersistentDispatcherSingleActiveConsumer
- ============= reScheduleRead ===========
2022-08-23T22:44:09,890+0800 [pulsar-io-766-7] INFO
org.apache.pulsar.broker.service.persistent.PersistentDispatcherSingleActiveConsumer
- ============= reScheduleRead ===========
2022-08-23T22:44:09,890+0800 [pulsar-io-766-8] INFO
org.apache.pulsar.broker.service.persistent.PersistentDispatcherSingleActiveConsumer
- ============= reScheduleRead ===========
2022-08-23T22:44:09,890+0800 [broker-topic-workers-OrderedExecutor-4-0] INFO
org.apache.pulsar.broker.service.persistent.PersistentDispatcherSingleActiveConsumer
- dispatch message ledger:3 entry:21
2022-08-23T22:44:09,890+0800 [broker-topic-workers-OrderedExecutor-4-0] INFO
org.apache.pulsar.broker.service.persistent.PersistentDispatcherSingleActiveConsumer
- dispatch message ledger:3 entry:21
2022-08-23T22:44:09,890+0800 [broker-topic-workers-OrderedExecutor-4-0] INFO
org.apache.pulsar.broker.service.persistent.PersistentDispatcherSingleActiveConsumer
- dispatch message ledger:3 entry:21
2022-08-23T22:44:09,890+0800 [broker-topic-workers-OrderedExecutor-4-0] INFO
org.apache.pulsar.broker.service.persistent.PersistentDispatcherSingleActiveConsumer
- ============= Dispatcher complete ===========
2022-08-23T22:44:09,890+0800 [broker-topic-workers-OrderedExecutor-4-0] INFO
org.apache.pulsar.broker.service.persistent.PersistentDispatcherSingleActiveConsumer
- dispatch message ledger:3 entry:22
2022-08-23T22:44:09,890+0800 [broker-topic-workers-OrderedExecutor-4-0] INFO
org.apache.pulsar.broker.service.persistent.PersistentDispatcherSingleActiveConsumer
- ============= Dispatcher complete ===========
2022-08-23T22:44:09,890+0800 [broker-topic-workers-OrderedExecutor-4-0] INFO
org.apache.pulsar.broker.service.persistent.PersistentDispatcherSingleActiveConsumer
- ============= Dispatcher complete ===========
2022-08-23T22:44:09,891+0800 [broker-topic-workers-OrderedExecutor-4-0] INFO
org.apache.pulsar.broker.service.persistent.PersistentDispatcherSingleActiveConsumer
- ============= internalConsumerFlow ===========
2022-08-23T22:44:10,891+0800 [pulsar-io-766-10] INFO
org.apache.pulsar.broker.service.persistent.PersistentDispatcherSingleActiveConsumer
- ============= reScheduleRead ===========
2022-08-23T22:44:10,891+0800 [pulsar-io-766-11] INFO
org.apache.pulsar.broker.service.persistent.PersistentDispatcherSingleActiveConsumer
- ============= reScheduleRead ===========
2022-08-23T22:44:10,891+0800 [pulsar-io-766-9] INFO
org.apache.pulsar.broker.service.persistent.PersistentDispatcherSingleActiveConsumer
- ============= reScheduleRead ===========
2022-08-23T22:44:10,892+0800 [broker-topic-workers-OrderedExecutor-4-0] INFO
org.apache.pulsar.broker.service.persistent.PersistentDispatcherSingleActiveConsumer
- dispatch message ledger:3 entry:23
2022-08-23T22:44:10,892+0800 [broker-topic-workers-OrderedExecutor-4-0] INFO
org.apache.pulsar.broker.service.persistent.PersistentDispatcherSingleActiveConsumer
- dispatch message ledger:3 entry:24
2022-08-23T22:44:10,892+0800 [broker-topic-workers-OrderedExecutor-4-0] INFO
org.apache.pulsar.broker.service.persistent.PersistentDispatcherSingleActiveConsumer
- dispatch message ledger:3 entry:25
2022-08-23T22:44:10,892+0800 [broker-topic-workers-OrderedExecutor-4-0] INFO
org.apache.pulsar.broker.service.persistent.PersistentDispatcherSingleActiveConsumer
- dispatch message ledger:3 entry:26
2022-08-23T22:44:10,892+0800 [broker-topic-workers-OrderedExecutor-4-0] INFO
org.apache.pulsar.broker.service.persistent.PersistentDispatcherSingleActiveConsumer
- dispatch message ledger:3 entry:23
2022-08-23T22:44:10,892+0800 [broker-topic-workers-OrderedExecutor-4-0] INFO
org.apache.pulsar.broker.service.persistent.PersistentDispatcherSingleActiveConsumer
- dispatch message ledger:3 entry:24
2022-08-23T22:44:10,892+0800 [broker-topic-workers-OrderedExecutor-4-0] INFO
org.apache.pulsar.broker.service.persistent.PersistentDispatcherSingleActiveConsumer
- dispatch message ledger:3 entry:25
2022-08-23T22:44:10,892+0800 [broker-topic-workers-OrderedExecutor-4-0] INFO
org.apache.pulsar.broker.service.persistent.PersistentDispatcherSingleActiveConsumer
- dispatch message ledger:3 entry:26
2022-08-23T22:44:10,892+0800 [broker-topic-workers-OrderedExecutor-4-0] INFO
org.apache.pulsar.broker.service.persistent.PersistentDispatcherSingleActiveConsumer
- dispatch message ledger:3 entry:23
2022-08-23T22:44:10,892+0800 [broker-topic-workers-OrderedExecutor-4-0] INFO
org.apache.pulsar.broker.service.persistent.PersistentDispatcherSingleActiveConsumer
- dispatch message ledger:3 entry:24
2022-08-23T22:44:10,892+0800 [broker-topic-workers-OrderedExecutor-4-0] INFO
org.apache.pulsar.broker.service.persistent.PersistentDispatcherSingleActiveConsumer
- dispatch message ledger:3 entry:25
2022-08-23T22:44:10,892+0800 [broker-topic-workers-OrderedExecutor-4-0] INFO
org.apache.pulsar.broker.service.persistent.PersistentDispatcherSingleActiveConsumer
- dispatch message ledger:3 entry:26
2022-08-23T22:44:10,892+0800 [broker-topic-workers-OrderedExecutor-4-0] INFO
org.apache.pulsar.broker.service.persistent.PersistentDispatcherSingleActiveConsumer
- ============= Dispatcher complete ===========
2022-08-23T22:44:10,892+0800 [broker-topic-workers-OrderedExecutor-4-0] INFO
org.apache.pulsar.broker.service.persistent.PersistentDispatcherSingleActiveConsumer
- ============= Dispatcher complete ===========
2022-08-23T22:44:10,893+0800 [broker-topic-workers-OrderedExecutor-4-0] INFO
org.apache.pulsar.broker.service.persistent.PersistentDispatcherSingleActiveConsumer
- ============= Dispatcher complete ===========
2022-08-23T22:44:10,893+0800 [broker-topic-workers-OrderedExecutor-4-0] INFO
org.apache.pulsar.broker.service.persistent.PersistentDispatcherSingleActiveConsumer
- ============= internalConsumerFlow ===========
2022-08-23T22:44:10,893+0800 [broker-topic-workers-OrderedExecutor-4-0] INFO
org.apache.pulsar.broker.service.persistent.PersistentDispatcherSingleActiveConsumer
- ============= internalConsumerFlow ===========
2022-08-23T22:44:11,556+0800 [pulsar-load-manager-763-1] INFO
org.apache.pulsar.broker.loadbalance.impl.ModularLoadManagerImpl - Writing
local data to metadata store because maximum change 19.620104134082794%
exceeded threshold 10%; time since last report written is 5.019 seconds
2022-08-23T22:44:11,560+0800 [metadata-store-771-1] INFO
org.apache.pulsar.metadata.coordination.impl.ResourceLockImpl - Acquired
resource lock on /loadbalance/brokers/localhost:56274
2022-08-23T22:44:11,893+0800 [pulsar-io-766-12] INFO
org.apache.pulsar.broker.service.persistent.PersistentDispatcherSingleActiveConsumer
- ============= reScheduleRead ===========
2022-08-23T22:44:11,894+0800 [pulsar-io-766-13] INFO
org.apache.pulsar.broker.service.persistent.PersistentDispatcherSingleActiveConsumer
- ============= reScheduleRead ===========
2022-08-23T22:44:11,894+0800 [pulsar-io-766-14] INFO
org.apache.pulsar.broker.service.persistent.PersistentDispatcherSingleActiveConsumer
- ============= reScheduleRead ===========
java.lang.AssertionError:
Expected :30.0
Actual :43.0
<Click to see difference>
at org.testng.Assert.fail(Assert.java:99)
at org.testng.Assert.failNotEquals(Assert.java:1037)
at org.testng.Assert.assertEquals(Assert.java:744)
at org.testng.Assert.assertEquals(Assert.java:757)
at
org.apache.pulsar.client.api.SubscriptionMessageDispatchThrottlingTest.testMessageNotDuplicated(SubscriptionMessageDispatchThrottlingTest.java:216)
at
java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:104)
at java.base/java.lang.reflect.Method.invoke(Method.java:577)
at
org.testng.internal.MethodInvocationHelper.invokeMethod(MethodInvocationHelper.java:132)
at
org.testng.internal.InvokeMethodRunnable.runOne(InvokeMethodRunnable.java:45)
at
org.testng.internal.InvokeMethodRunnable.call(InvokeMethodRunnable.java:73)
at
org.testng.internal.InvokeMethodRunnable.call(InvokeMethodRunnable.java:11)
at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
at
java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
at
java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
at java.base/java.lang.Thread.run(Thread.java:833)
```
From this log, we can know `internalConsumerFlow` and `reScheduleRead` will
invoke many times concurrently. and the `reScheduleRead` may have some problems
cause we register many scheduled tasks on it. I will try fix it at another 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: [email protected]
For queries about this service, please contact Infrastructure at:
[email protected]
