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][broker] Fix dispatch duplicated messages with Exclusive mode. #17237

Merged
merged 6 commits into from
Aug 24, 2022
Merged

[fix][broker] Fix dispatch duplicated messages with Exclusive mode. #17237

merged 6 commits into from
Aug 24, 2022

Conversation

mattisonchao
Copy link
Member

@mattisonchao mattisonchao commented Aug 23, 2022

Motivation

When invoking readMoreEntries we have to check if the havePendingRead state is true to avoid reading the same position many times in the race condition.

You can add invocationCount on the Test annotation to call the new test multiple times to understand the problem.

The relative logs:

2022-08-23T19:10:01,016 - INFO  - [pulsar-web-191-16:Slf4jRequestLogWriter@62] - 127.0.0.1 - - [23/Aug/2022:19:10:01 +0800] "GET /admin/v2/namespaces/my-property/throttling_ns/subscriptionDispatchRate HTTP/1.1" 200 124 "-" "Pulsar-Java-v2.11.0-SNAPSHOT" 2
2022-08-23T19:10:01,019 - INFO  - [pulsar-web-191-14:Slf4jRequestLogWriter@62] - 127.0.0.1 - - [23/Aug/2022:19:10:01 +0800] "GET /admin/v2/namespaces/my-property/throttling_ns/dispatchRate HTTP/1.1" 200 123 "-" "Pulsar-Java-v2.11.0-SNAPSHOT" 2
2022-08-23T19:10:01,021 - INFO  - [broker-topic-workers-OrderedExecutor-7-0:PersistentDispatcherSingleActiveConsumer@162] - ============ before dispatch
2022-08-23T19:10:01,021 - INFO  - [broker-topic-workers-OrderedExecutor-7-0:PersistentDispatcherSingleActiveConsumer@164] - dispatch message to consumer ledger:3, entry:0
2022-08-23T19:10:01,021 - INFO  - [broker-topic-workers-OrderedExecutor-7-0:PersistentDispatcherSingleActiveConsumer@166] - ============ after dispatch
2022-08-23T19:10:01,023 - INFO  - [pulsar-external-listener-197-1:SubscriptionMessageDispatchThrottlingTest@346] - Received message [0] in the listener
2022-08-23T19:10:01,036 - INFO  - [broker-topic-workers-OrderedExecutor-7-0:PersistentDispatcherSingleActiveConsumer@162] - ============ before dispatch
2022-08-23T19:10:01,036 - INFO  - [broker-topic-workers-OrderedExecutor-7-0:PersistentDispatcherSingleActiveConsumer@164] - dispatch message to consumer ledger:3, entry:1
2022-08-23T19:10:01,036 - INFO  - [broker-topic-workers-OrderedExecutor-7-0:PersistentDispatcherSingleActiveConsumer@164] - dispatch message to consumer ledger:3, entry:2
2022-08-23T19:10:01,036 - INFO  - [broker-topic-workers-OrderedExecutor-7-0:PersistentDispatcherSingleActiveConsumer@164] - dispatch message to consumer ledger:3, entry:3
2022-08-23T19:10:01,036 - INFO  - [broker-topic-workers-OrderedExecutor-7-0:PersistentDispatcherSingleActiveConsumer@164] - dispatch message to consumer ledger:3, entry:4
2022-08-23T19:10:01,036 - INFO  - [broker-topic-workers-OrderedExecutor-7-0:PersistentDispatcherSingleActiveConsumer@164] - dispatch message to consumer ledger:3, entry:5
2022-08-23T19:10:01,036 - INFO  - [broker-topic-workers-OrderedExecutor-7-0:PersistentDispatcherSingleActiveConsumer@166] - ============ after dispatch
2022-08-23T19:10:01,037 - INFO  - [pulsar-external-listener-197-1:SubscriptionMessageDispatchThrottlingTest@346] - Received message [1] in the listener
2022-08-23T19:10:01,037 - INFO  - [pulsar-external-listener-197-1:SubscriptionMessageDispatchThrottlingTest@346] - Received message [2] in the listener
2022-08-23T19:10:01,037 - INFO  - [pulsar-external-listener-197-1:SubscriptionMessageDispatchThrottlingTest@346] - Received message [3] in the listener
2022-08-23T19:10:01,037 - INFO  - [pulsar-external-listener-197-1:SubscriptionMessageDispatchThrottlingTest@346] - Received message [4] in the listener
2022-08-23T19:10:01,037 - INFO  - [pulsar-external-listener-197-1:SubscriptionMessageDispatchThrottlingTest@346] - Received message [5] in the listener
2022-08-23T19:10:01,037 - INFO  - [broker-topic-workers-OrderedExecutor-7-0:PersistentDispatcherSingleActiveConsumer@162] - ============ before dispatch
2022-08-23T19:10:01,037 - INFO  - [broker-topic-workers-OrderedExecutor-7-0:PersistentDispatcherSingleActiveConsumer@164] - dispatch message to consumer ledger:3, entry:6
2022-08-23T19:10:01,037 - INFO  - [broker-topic-workers-OrderedExecutor-7-0:PersistentDispatcherSingleActiveConsumer@166] - ============ after dispatch
2022-08-23T19:10:01,038 - INFO  - [broker-topic-workers-OrderedExecutor-7-0:PersistentDispatcherSingleActiveConsumer@162] - ============ before dispatch
2022-08-23T19:10:01,038 - INFO  - [broker-topic-workers-OrderedExecutor-7-0:PersistentDispatcherSingleActiveConsumer@164] - dispatch message to consumer ledger:3, entry:7
2022-08-23T19:10:01,038 - INFO  - [broker-topic-workers-OrderedExecutor-7-0:PersistentDispatcherSingleActiveConsumer@166] - ============ after dispatch
2022-08-23T19:10:01,038 - INFO  - [pulsar-external-listener-197-1:SubscriptionMessageDispatchThrottlingTest@346] - Received message [6] in the listener
2022-08-23T19:10:01,038 - INFO  - [pulsar-external-listener-197-1:SubscriptionMessageDispatchThrottlingTest@346] - Received message [7] in the listener
2022-08-23T19:10:02,039 - INFO  - [broker-topic-workers-OrderedExecutor-7-0:PersistentDispatcherSingleActiveConsumer@162] - ============ before dispatch
2022-08-23T19:10:02,039 - INFO  - [broker-topic-workers-OrderedExecutor-7-0:PersistentDispatcherSingleActiveConsumer@164] - dispatch message to consumer ledger:3, entry:8
2022-08-23T19:10:02,039 - INFO  - [broker-topic-workers-OrderedExecutor-7-0:PersistentDispatcherSingleActiveConsumer@164] - dispatch message to consumer ledger:3, entry:9
2022-08-23T19:10:02,039 - INFO  - [broker-topic-workers-OrderedExecutor-7-0:PersistentDispatcherSingleActiveConsumer@164] - dispatch message to consumer ledger:3, entry:10
2022-08-23T19:10:02,039 - INFO  - [broker-topic-workers-OrderedExecutor-7-0:PersistentDispatcherSingleActiveConsumer@164] - dispatch message to consumer ledger:3, entry:11
2022-08-23T19:10:02,039 - INFO  - [broker-topic-workers-OrderedExecutor-7-0:PersistentDispatcherSingleActiveConsumer@164] - dispatch message to consumer ledger:3, entry:12
2022-08-23T19:10:02,039 - INFO  - [broker-topic-workers-OrderedExecutor-7-0:PersistentDispatcherSingleActiveConsumer@166] - ============ after dispatch
2022-08-23T19:10:02,039 - INFO  - [broker-topic-workers-OrderedExecutor-7-0:PersistentDispatcherSingleActiveConsumer@162] - ============ before dispatch
2022-08-23T19:10:02,039 - INFO  - [broker-topic-workers-OrderedExecutor-7-0:PersistentDispatcherSingleActiveConsumer@164] - dispatch message to consumer ledger:3, entry:13
2022-08-23T19:10:02,039 - INFO  - [broker-topic-workers-OrderedExecutor-7-0:PersistentDispatcherSingleActiveConsumer@164] - dispatch message to consumer ledger:3, entry:14
2022-08-23T19:10:02,040 - INFO  - [broker-topic-workers-OrderedExecutor-7-0:PersistentDispatcherSingleActiveConsumer@164] - dispatch message to consumer ledger:3, entry:15
2022-08-23T19:10:02,040 - INFO  - [broker-topic-workers-OrderedExecutor-7-0:PersistentDispatcherSingleActiveConsumer@164] - dispatch message to consumer ledger:3, entry:16
2022-08-23T19:10:02,040 - INFO  - [broker-topic-workers-OrderedExecutor-7-0:PersistentDispatcherSingleActiveConsumer@164] - dispatch message to consumer ledger:3, entry:17
2022-08-23T19:10:02,040 - INFO  - [broker-topic-workers-OrderedExecutor-7-0:PersistentDispatcherSingleActiveConsumer@166] - ============ after dispatch
2022-08-23T19:10:02,041 - INFO  - [pulsar-external-listener-197-1:SubscriptionMessageDispatchThrottlingTest@346] - Received message [8] in the listener
2022-08-23T19:10:02,041 - INFO  - [pulsar-external-listener-197-1:SubscriptionMessageDispatchThrottlingTest@346] - Received message [9] in the listener
2022-08-23T19:10:02,041 - INFO  - [pulsar-external-listener-197-1:SubscriptionMessageDispatchThrottlingTest@346] - Received message [10] in the listener
2022-08-23T19:10:02,041 - INFO  - [pulsar-external-listener-197-1:SubscriptionMessageDispatchThrottlingTest@346] - Received message [11] in the listener
2022-08-23T19:10:02,041 - INFO  - [pulsar-external-listener-197-1:SubscriptionMessageDispatchThrottlingTest@346] - Received message [12] in the listener
2022-08-23T19:10:02,041 - INFO  - [pulsar-external-listener-197-1:SubscriptionMessageDispatchThrottlingTest@346] - Received message [13] in the listener
2022-08-23T19:10:02,041 - INFO  - [pulsar-external-listener-197-1:SubscriptionMessageDispatchThrottlingTest@346] - Received message [14] in the listener
2022-08-23T19:10:02,041 - INFO  - [pulsar-external-listener-197-1:SubscriptionMessageDispatchThrottlingTest@346] - Received message [15] in the listener
2022-08-23T19:10:02,041 - INFO  - [pulsar-external-listener-197-1:SubscriptionMessageDispatchThrottlingTest@346] - Received message [16] in the listener
2022-08-23T19:10:02,041 - INFO  - [pulsar-external-listener-197-1:SubscriptionMessageDispatchThrottlingTest@346] - Received message [17] in the listener
2022-08-23T19:10:03,042 - INFO  - [broker-topic-workers-OrderedExecutor-7-0:PersistentDispatcherSingleActiveConsumer@162] - ============ before dispatch
2022-08-23T19:10:03,042 - INFO  - [broker-topic-workers-OrderedExecutor-7-0:PersistentDispatcherSingleActiveConsumer@164] - dispatch message to consumer ledger:3, entry:18
2022-08-23T19:10:03,042 - INFO  - [broker-topic-workers-OrderedExecutor-7-0:PersistentDispatcherSingleActiveConsumer@166] - ============ after dispatch
2022-08-23T19:10:03,043 - INFO  - [broker-topic-workers-OrderedExecutor-7-0:PersistentDispatcherSingleActiveConsumer@162] - ============ before dispatch
2022-08-23T19:10:03,043 - INFO  - [broker-topic-workers-OrderedExecutor-7-0:PersistentDispatcherSingleActiveConsumer@164] - dispatch message to consumer ledger:3, entry:18
2022-08-23T19:10:03,043 - INFO  - [broker-topic-workers-OrderedExecutor-7-0:PersistentDispatcherSingleActiveConsumer@166] - ============ after dispatch
2022-08-23T19:10:03,043 - INFO  - [broker-topic-workers-OrderedExecutor-7-0:PersistentDispatcherSingleActiveConsumer@162] - ============ before dispatch
2022-08-23T19:10:03,043 - INFO  - [broker-topic-workers-OrderedExecutor-7-0:PersistentDispatcherSingleActiveConsumer@164] - dispatch message to consumer ledger:3, entry:19
2022-08-23T19:10:03,043 - INFO  - [pulsar-external-listener-197-1:SubscriptionMessageDispatchThrottlingTest@346] - Received message [18] in the listener
2022-08-23T19:10:03,044 - INFO  - [broker-topic-workers-OrderedExecutor-7-0:PersistentDispatcherSingleActiveConsumer@166] - ============ after dispatch
2022-08-23T19:10:03,044 - INFO  - [pulsar-external-listener-197-1:SubscriptionMessageDispatchThrottlingTest@346] - Received message [18] in the listener
2022-08-23T19:10:03,044 - INFO  - [pulsar-external-listener-197-1:SubscriptionMessageDispatchThrottlingTest@346] - Received message [19] in the listener
2022-08-23T19:10:04,045 - INFO  - [broker-topic-workers-OrderedExecutor-7-0:PersistentDispatcherSingleActiveConsumer@162] - ============ before dispatch
2022-08-23T19:10:04,045 - INFO  - [broker-topic-workers-OrderedExecutor-7-0:PersistentDispatcherSingleActiveConsumer@164] - dispatch message to consumer ledger:3, entry:20
2022-08-23T19:10:04,045 - INFO  - [broker-topic-workers-OrderedExecutor-7-0:PersistentDispatcherSingleActiveConsumer@164] - dispatch message to consumer ledger:3, entry:21
2022-08-23T19:10:04,045 - INFO  - [broker-topic-workers-OrderedExecutor-7-0:PersistentDispatcherSingleActiveConsumer@164] - dispatch message to consumer ledger:3, entry:22
2022-08-23T19:10:04,045 - INFO  - [broker-topic-workers-OrderedExecutor-7-0:PersistentDispatcherSingleActiveConsumer@164] - dispatch message to consumer ledger:3, entry:23
2022-08-23T19:10:04,045 - INFO  - [broker-topic-workers-OrderedExecutor-7-0:PersistentDispatcherSingleActiveConsumer@166] - ============ after dispatch
2022-08-23T19:10:04,045 - INFO  - [broker-topic-workers-OrderedExecutor-7-0:PersistentDispatcherSingleActiveConsumer@162] - ============ before dispatch
2022-08-23T19:10:04,045 - INFO  - [broker-topic-workers-OrderedExecutor-7-0:PersistentDispatcherSingleActiveConsumer@164] - dispatch message to consumer ledger:3, entry:20
2022-08-23T19:10:04,045 - INFO  - [broker-topic-workers-OrderedExecutor-7-0:PersistentDispatcherSingleActiveConsumer@164] - dispatch message to consumer ledger:3, entry:21
2022-08-23T19:10:04,045 - INFO  - [broker-topic-workers-OrderedExecutor-7-0:PersistentDispatcherSingleActiveConsumer@164] - dispatch message to consumer ledger:3, entry:22
2022-08-23T19:10:04,046 - INFO  - [broker-topic-workers-OrderedExecutor-7-0:PersistentDispatcherSingleActiveConsumer@164] - dispatch message to consumer ledger:3, entry:23
2022-08-23T19:10:04,046 - INFO  - [broker-topic-workers-OrderedExecutor-7-0:PersistentDispatcherSingleActiveConsumer@166] - ============ after dispatch
2022-08-23T19:10:04,046 - INFO  - [pulsar-external-listener-197-1:SubscriptionMessageDispatchThrottlingTest@346] - Received message [20] in the listener
2022-08-23T19:10:04,047 - INFO  - [pulsar-external-listener-197-1:SubscriptionMessageDispatchThrottlingTest@346] - Received message [21] in the listener
2022-08-23T19:10:04,047 - INFO  - [pulsar-external-listener-197-1:SubscriptionMessageDispatchThrottlingTest@346] - Received message [22] in the listener
2022-08-23T19:10:04,047 - INFO  - [pulsar-external-listener-197-1:SubscriptionMessageDispatchThrottlingTest@346] - Received message [23] in the listener
2022-08-23T19:10:04,047 - INFO  - [pulsar-external-listener-197-1:SubscriptionMessageDispatchThrottlingTest@346] - Received message [20] in the listener
2022-08-23T19:10:04,047 - INFO  - [pulsar-external-listener-197-1:SubscriptionMessageDispatchThrottlingTest@346] - Received message [21] in the listener
2022-08-23T19:10:04,047 - INFO  - [pulsar-external-listener-197-1:SubscriptionMessageDispatchThrottlingTest@346] - Received message [22] in the listener
2022-08-23T19:10:04,047 - INFO  - [pulsar-external-listener-197-1:SubscriptionMessageDispatchThrottlingTest@346] - Received message [23] in the listener
2022-08-23T19:10:05,048 - INFO  - [broker-topic-workers-OrderedExecutor-7-0:PersistentDispatcherSingleActiveConsumer@162] - ============ before dispatch
2022-08-23T19:10:05,048 - INFO  - [broker-topic-workers-OrderedExecutor-7-0:PersistentDispatcherSingleActiveConsumer@164] - dispatch message to consumer ledger:3, entry:24
2022-08-23T19:10:05,048 - INFO  - [broker-topic-workers-OrderedExecutor-7-0:PersistentDispatcherSingleActiveConsumer@164] - dispatch message to consumer ledger:3, entry:25
2022-08-23T19:10:05,048 - INFO  - [broker-topic-workers-OrderedExecutor-7-0:PersistentDispatcherSingleActiveConsumer@164] - dispatch message to consumer ledger:3, entry:26
2022-08-23T19:10:05,048 - INFO  - [broker-topic-workers-OrderedExecutor-7-0:PersistentDispatcherSingleActiveConsumer@166] - ============ after dispatch
2022-08-23T19:10:05,048 - INFO  - [broker-topic-workers-OrderedExecutor-7-0:PersistentDispatcherSingleActiveConsumer@162] - ============ before dispatch
2022-08-23T19:10:05,048 - INFO  - [broker-topic-workers-OrderedExecutor-7-0:PersistentDispatcherSingleActiveConsumer@164] - dispatch message to consumer ledger:3, entry:24
2022-08-23T19:10:05,048 - INFO  - [broker-topic-workers-OrderedExecutor-7-0:PersistentDispatcherSingleActiveConsumer@164] - dispatch message to consumer ledger:3, entry:25
2022-08-23T19:10:05,048 - INFO  - [broker-topic-workers-OrderedExecutor-7-0:PersistentDispatcherSingleActiveConsumer@164] - dispatch message to consumer ledger:3, entry:26
2022-08-23T19:10:05,048 - INFO  - [broker-topic-workers-OrderedExecutor-7-0:PersistentDispatcherSingleActiveConsumer@166] - ============ after dispatch
2022-08-23T19:10:05,049 - INFO  - [pulsar-external-listener-197-1:SubscriptionMessageDispatchThrottlingTest@346] - Received message [24] in the listener
2022-08-23T19:10:05,049 - INFO  - [pulsar-external-listener-197-1:SubscriptionMessageDispatchThrottlingTest@346] - Received message [25] in the listener
2022-08-23T19:10:05,049 - INFO  - [pulsar-external-listener-197-1:SubscriptionMessageDispatchThrottlingTest@346] - Received message [26] in the listener
2022-08-23T19:10:05,049 - INFO  - [pulsar-external-listener-197-1:SubscriptionMessageDispatchThrottlingTest@346] - Received message [24] in the listener
2022-08-23T19:10:05,049 - INFO  - [pulsar-external-listener-197-1:SubscriptionMessageDispatchThrottlingTest@346] - Received message [25] in the listener
2022-08-23T19:10:05,050 - INFO  - [pulsar-external-listener-197-1:SubscriptionMessageDispatchThrottlingTest@346] - Received message [26] in the listener
2022-08-23T19:10:05,659 - INFO  - [pulsar-load-manager-163-1:ModularLoadManagerImpl@466] - Writing local data to metadata store because maximum change 55.46875% exceeded threshold 10%; time since last report written is 5.02 seconds. ResourceUsage:[cpu: 11.06%, memory: 55.47%, directMemory: 9.38%, bandwidthIn: 0.00%, bandwidthOut: 0.00%]
2022-08-23T19:10:05,661 - INFO  - [metadata-store-171-1:ResourceLockImpl@165] - Acquired resource lock on /loadbalance/brokers/localhost:52221
2022-08-23T19:10:06,053 - INFO  - [broker-topic-workers-OrderedExecutor-7-0:PersistentDispatcherSingleActiveConsumer@162] - ============ before dispatch
2022-08-23T19:10:06,053 - INFO  - [broker-topic-workers-OrderedExecutor-7-0:PersistentDispatcherSingleActiveConsumer@164] - dispatch message to consumer ledger:3, entry:27
2022-08-23T19:10:06,053 - INFO  - [broker-topic-workers-OrderedExecutor-7-0:PersistentDispatcherSingleActiveConsumer@164] - dispatch message to consumer ledger:3, entry:28
2022-08-23T19:10:06,053 - INFO  - [broker-topic-workers-OrderedExecutor-7-0:PersistentDispatcherSingleActiveConsumer@164] - dispatch message to consumer ledger:3, entry:29
2022-08-23T19:10:06,053 - INFO  - [broker-topic-workers-OrderedExecutor-7-0:PersistentDispatcherSingleActiveConsumer@166] - ============ after dispatch
2022-08-23T19:10:06,053 - INFO  - [broker-topic-workers-OrderedExecutor-7-0:PersistentDispatcherSingleActiveConsumer@162] - ============ before dispatch
2022-08-23T19:10:06,053 - INFO  - [broker-topic-workers-OrderedExecutor-7-0:PersistentDispatcherSingleActiveConsumer@164] - dispatch message to consumer ledger:3, entry:27
2022-08-23T19:10:06,053 - INFO  - [broker-topic-workers-OrderedExecutor-7-0:PersistentDispatcherSingleActiveConsumer@164] - dispatch message to consumer ledger:3, entry:28
2022-08-23T19:10:06,053 - INFO  - [broker-topic-workers-OrderedExecutor-7-0:PersistentDispatcherSingleActiveConsumer@164] - dispatch message to consumer ledger:3, entry:29
2022-08-23T19:10:06,053 - INFO  - [broker-topic-workers-OrderedExecutor-7-0:PersistentDispatcherSingleActiveConsumer@166] - ============ after dispatch
2022-08-23T19:10:06,056 - INFO  - [pulsar-external-listener-197-1:SubscriptionMessageDispatchThrottlingTest@346] - Received message [27] in the listener
2022-08-23T19:10:06,056 - INFO  - [pulsar-external-listener-197-1:SubscriptionMessageDispatchThrottlingTest@346] - Received message [28] in the listener
2022-08-23T19:10:06,056 - INFO  - [pulsar-external-listener-197-1:SubscriptionMessageDispatchThrottlingTest@346] - Received message [29] in the listener
2022-08-23T19:10:06,056 - INFO  - [pulsar-external-listener-197-1:SubscriptionMessageDispatchThrottlingTest@346] - Received message [27] in the listener
2022-08-23T19:10:06,056 - INFO  - [pulsar-external-listener-197-1:SubscriptionMessageDispatchThrottlingTest@346] - Received message [28] in the listener
2022-08-23T19:10:06,056 - INFO  - [pulsar-external-listener-197-1:SubscriptionMessageDispatchThrottlingTest@346] - Received message [29] in the listener

java.lang.AssertionError: 
Expected :30.0
Actual   :41.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.testDispatchRate(SubscriptionMessageDispatchThrottlingTest.java:390)
	at org.apache.pulsar.client.api.SubscriptionMessageDispatchThrottlingTest.testMultiLevelDispatch(SubscriptionMessageDispatchThrottlingTest.java:420)
	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.TestInvoker.invokeMethod(TestInvoker.java:599)
	at org.testng.internal.TestInvoker.invokeTestMethod(TestInvoker.java:174)
	at org.testng.internal.MethodRunner.runInSequence(MethodRunner.java:46)
	at org.testng.internal.TestInvoker$MethodInvocationAgent.invoke(TestInvoker.java:822)
	at org.testng.internal.TestInvoker.invokeTestMethods(TestInvoker.java:147)
	at org.testng.internal.TestMethodWorker.invokeTestMethods(TestMethodWorker.java:146)
	at org.testng.internal.TestMethodWorker.run(TestMethodWorker.java:128)
	at java.base/java.util.ArrayList.forEach(ArrayList.java:1511)
	at org.testng.TestRunner.privateRun(TestRunner.java:764)
	at org.testng.TestRunner.run(TestRunner.java:585)
	at org.testng.SuiteRunner.runTest(SuiteRunner.java:384)
	at org.testng.SuiteRunner.runSequentially(SuiteRunner.java:378)
	at org.testng.SuiteRunner.privateRun(SuiteRunner.java:337)
	at org.testng.SuiteRunner.run(SuiteRunner.java:286)
	at org.testng.SuiteRunnerWorker.runSuite(SuiteRunnerWorker.java:53)
	at org.testng.SuiteRunnerWorker.run(SuiteRunnerWorker.java:96)
	at org.testng.TestNG.runSuitesSequentially(TestNG.java:1218)
	at org.testng.TestNG.runSuitesLocally(TestNG.java:1140)
	at org.testng.TestNG.runSuites(TestNG.java:1069)
	at org.testng.TestNG.run(TestNG.java:1037)
	at com.intellij.rt.testng.IDEARemoteTestNG.run(IDEARemoteTestNG.java:66)
	at com.intellij.rt.testng.RemoteTestNGStarter.main(RemoteTestNGStarter.java:109)

Modifications

  • Add synchronized keyword and havePendingRead state to avoid read same position many times.
  • Clean up the unnecessary havePendingRead check.

Verifying this change

  • Make sure that the change passes the CI checks.

Documentation

Check the box below or label this PR directly.

Need to update docs?

  • 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)

@mattisonchao mattisonchao self-assigned this Aug 23, 2022
@mattisonchao
Copy link
Member Author

I will add more information later

@mattisonchao mattisonchao marked this pull request as draft August 23, 2022 11:54
@mattisonchao mattisonchao marked this pull request as ready for review August 23, 2022 14:28
@mattisonchao
Copy link
Member Author

mattisonchao commented Aug 23, 2022

Because branch-2.10 also has this problem. I don't think it's a 2.11 release blocker.

image

@mattisonchao mattisonchao added this to the 2.12.0 milestone Aug 23, 2022
@mattisonchao
Copy link
Member Author

mattisonchao commented Aug 23, 2022

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.

Copy link
Contributor

@nicoloboschi nicoloboschi left a comment

Choose a reason for hiding this comment

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

LGTM
great catch!

Copy link
Contributor

@codelipenghui codelipenghui left a comment

Choose a reason for hiding this comment

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

The change looks good to me.

@codelipenghui
Copy link
Contributor

@mattisonchao Do you know which PR introduced this issue?

@eolivelli
Copy link
Contributor

This is very interesting.
How did you find this problem ?
It doesn't look like a regression of code contributed recently

Copy link
Member

@michaeljmarshall michaeljmarshall left a comment

Choose a reason for hiding this comment

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

Great catch. Do we have an idea of what is causing the early calls to the readMoreEntries method? Adding synchronize will ensure correctness, but it might also increase contention and slow down the dispatcher.

@@ -332,12 +332,17 @@ public void redeliverUnacknowledgedMessages(Consumer consumer, List<PositionImpl
}

@Override
protected void readMoreEntries(Consumer consumer) {
protected synchronized void readMoreEntries(Consumer consumer) {
Copy link
Member

Choose a reason for hiding this comment

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

It seems like we might not want to acquire the lock before the consumer null check.

Copy link
Member Author

Choose a reason for hiding this comment

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

Modified the scope of the lock

// consumer can be null when all consumers are disconnected from broker.
// so skip reading more entries if currently there is no active consumer.
if (null == consumer) {
return;
}
if (havePendingRead) {
Copy link
Member

Choose a reason for hiding this comment

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

I see several parts of the code that call this readMoreEntries method after verifying that havePendingRead is true. I haven't yet verified the details of each call, but it seems like we should clean up those guards if we are moving the logic into this method.

Copy link
Member Author

Choose a reason for hiding this comment

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

I think we should move the havePendingRead check to the readMoreEntries method to avoid judgement everywhere.
Except for some judgments that have logical implications, I have changed them all.
Please take a look.

Pair<Integer, Long> calculateResult = calculateToRead(consumer);
int messagesToRead = calculateResult.getLeft();
long bytesToRead = calculateResult.getRight();
synchronized (this) {
Copy link
Member Author

Choose a reason for hiding this comment

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

Move lock here to avoid invoking useless calculateToRead many times.

+ " havePendingRead {}",
topic.getName(), currentConsumer, havePendingRead);
}
if (isRescheduleReadInProgress.compareAndSet(false, true)) {
Copy link
Member Author

Choose a reason for hiding this comment

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

We have to avoid reScheduleRead many times, see #16241

@mattisonchao
Copy link
Member Author

mattisonchao commented Aug 24, 2022

After the test, I think the problem was caused by we probably invoking reScheduleRead many times, and the readMoreEntires also don't have havePendingRead guard. #17237 (comment)

So, we may read the same position many times.

Even though I fix the reSheduledRead many times, I still think we need to add havePendingRead guard at readMoreEntires method.

@mattisonchao
Copy link
Member Author

mattisonchao commented Aug 24, 2022

Hi @eolivelli

How did you find this problem ?

When I wanted to fix the flaky test "SubscriptionMessageDispatchThrottlingTest", I found that one time we received more messages than we sent. So, I added Thread.sleep() to verify it.

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.

LGTM
good catch !

@eolivelli eolivelli changed the title [fix][broker] Fix dispatch the duplicated message with Exclusive mode. [fix][broker] Fix dispatch duplicated messages with Exclusive mode. Aug 24, 2022
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

Comment on lines +300 to +301
// If this assertion failed, please alert we may have some regression cause message dispatch was duplicated.
Assert.assertEquals(totalReceived.get(), numProducedMessages, 10);
Copy link
Member

Choose a reason for hiding this comment

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

This is flaky. since the comment is "please alert", I'm alerting. :)

Copy link
Member

Choose a reason for hiding this comment

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

I was running it locally.

java.lang.AssertionError: 
Expected :30.0
Actual   :44.0

Copy link
Member Author

@mattisonchao mattisonchao Aug 26, 2022

Choose a reason for hiding this comment

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

I will try to verify it. Maybe I lost something. very thanks to you!

Nicklee007 pushed a commit to Nicklee007/pulsar that referenced this pull request Aug 29, 2022
@syhily
Copy link

syhily commented Sep 5, 2022

We meet same issue here on flink-connector-pulsar.

Sep 05 05:19:03 [ERROR] org.apache.flink.connector.pulsar.source.reader.split.PulsarOrderedPartitionSplitReaderTest.consumeMessageCreatedBeforeHandleSplitsChangesAndResetToEarliestPosition(PulsarPartitionSplitReaderBase)[1]  Time elapsed: 30.569 s  <<< FAILURE!
Sep 05 05:19:03 java.lang.AssertionError: 
Sep 05 05:19:03 [We should fetch the expected size] 
Sep 05 05:19:03 Expected size: 20 but was: 23 in:
Sep 05 05:19:03 [PulsarMessage{id=148:0:0, value=xtvCoENDyD, eventTime=0},
Sep 05 05:19:03     PulsarMessage{id=148:1:0, value=LsfmAdOvPi, eventTime=0},
Sep 05 05:19:03     PulsarMessage{id=148:2:0, value=SADrPXpnsp, eventTime=0},
Sep 05 05:19:03     PulsarMessage{id=148:0:0, value=xtvCoENDyD, eventTime=0},
Sep 05 05:19:03     PulsarMessage{id=148:1:0, value=LsfmAdOvPi, eventTime=0},
Sep 05 05:19:03     PulsarMessage{id=148:2:0, value=SADrPXpnsp, eventTime=0},
Sep 05 05:19:03     PulsarMessage{id=148:3:0, value=BsEGjUZSJN, eventTime=0},
Sep 05 05:19:03     PulsarMessage{id=148:4:0, value=wvteCkUkjX, eventTime=0},
Sep 05 05:19:03     PulsarMessage{id=148:5:0, value=HUEpGPmjYy, eventTime=0},
Sep 05 05:19:03     PulsarMessage{id=148:6:0, value=kndeIFjLLK, eventTime=0},
Sep 05 05:19:03     PulsarMessage{id=148:7:0, value=gOmuNzCqbL, eventTime=0},
Sep 05 05:19:03     PulsarMessage{id=148:8:0, value=fvtNHyyqqj, eventTime=0},
Sep 05 05:19:03     PulsarMessage{id=148:9:0, value=iKrmISirqy, eventTime=0},
Sep 05 05:19:03     PulsarMessage{id=148:10:0, value=lQUCdQizRw, eventTime=0},
Sep 05 05:19:03     PulsarMessage{id=148:11:0, value=RkGRkfTAcS, eventTime=0},
Sep 05 05:19:03     PulsarMessage{id=148:12:0, value=mBcAGPkmpY, eventTime=0},
Sep 05 05:19:03     PulsarMessage{id=148:13:0, value=AMUWkVFpwU, eventTime=0},
Sep 05 05:19:03     PulsarMessage{id=148:14:0, value=zCtbxzylrl, eventTime=0},
Sep 05 05:19:03     PulsarMessage{id=148:15:0, value=OQNrSEYkFo, eventTime=0},
Sep 05 05:19:03     PulsarMessage{id=148:16:0, value=oLuIyaJZrI, eventTime=0},
Sep 05 05:19:03     PulsarMessage{id=148:17:0, value=PfbbxVuQKh, eventTime=0},
Sep 05 05:19:03     PulsarMessage{id=148:18:0, value=KeIgSeYDxM, eventTime=0},
Sep 05 05:19:03     PulsarMessage{id=148:19:0, value=KZkeATFOln, eventTime=0}]
Sep 05 05:19:03 	at org.apache.flink.connector.pulsar.source.reader.split.PulsarPartitionSplitReaderTestBase.fetchedMessages(PulsarPartitionSplitReaderTestBase.java:199)
Sep 05 05:19:03 	at org.apache.flink.connector.pulsar.source.reader.split.PulsarPartitionSplitReaderTestBase.fetchedMessages(PulsarPartitionSplitReaderTestBase.java:169)
Sep 05 05:19:03 	at org.apache.flink.connector.pulsar.source.reader.split.PulsarPartitionSplitReaderTestBase.consumeMessageCreatedBeforeHandleSplitsChangesAndResetToEarliestPosition(PulsarPartitionSplitReaderTestBase.java:260)

liangyepianzhou pushed a commit that referenced this pull request Dec 6, 2022
nicoloboschi pushed a commit to datastax/pulsar that referenced this pull request Dec 7, 2022
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

Successfully merging this pull request may close these issues.

10 participants