Adding more permits debug statements to better diagnose permit issues #10217

devinbost · 2021-04-13T19:26:29Z

This PR just adds debug statements whenever the broker updates its permits in broker.service.Consumer and in PersistentDispatcherMultipleConsumers. It also adds batch sizes to some of the debug log statements.
That will help with the forensic analysis of problematic permit behavior.

devinbost · 2021-04-13T19:28:09Z

@merlimat @eolivelli Since it's not easy to get debug logs from functions due to #3259, I added more logs to the broker instead.

merlimat · 2021-04-13T22:01:17Z

@devinbost There are few checkstyle violations reported in the CI jobs:

Error:  src/main/java/org/apache/pulsar/broker/service/PulsarCommandSenderImpl.java:[254] (sizes) LineLength: Line is longer than 120 characters (found 130).
5726
Error:  src/main/java/org/apache/pulsar/broker/service/persistent/PersistentDispatcherMultipleConsumers.java:[189,119] (whitespace) OperatorWrap: '+' should be on a new line.
5727
Error:  src/main/java/org/apache/pulsar/broker/service/persistent/PersistentDispatcherMultipleConsumers.java:[212,104] (whitespace) OperatorWrap: '+' should be on a new line.
5728
Error:  src/main/java/org/apache/pulsar/broker/service/persistent/PersistentDispatcherMultipleConsumers.java:[496,98] (whitespace) OperatorWrap: '+' should be on a new line.
5729
Error:  src/main/java/org/apache/pulsar/broker/service/persistent/PersistentDispatcherMultipleConsumers.java:[529,17] (whitespace) WhitespaceAround: 'if' is not followed by whitespace.
5730
Error:  src/main/java/org/apache/pulsar/broker/service/persistent/PersistentDispatcherMultipleConsumers.java:[530,106] (whitespace) OperatorWrap: '+' should be on a new line.
5731
Error:  src/main/java/org/apache/pulsar/broker/service/Consumer.java:[239,21] (whitespace) WhitespaceAround: 'if' is not followed by whitespace.
5732
Error:  src/main/java/org/apache/pulsar/broker/service/Consumer.java:[240,109] (whitespace) OperatorWrap: '+' should be on a new line.
5733
Error:  src/main/java/org/apache/pulsar/broker/service/Consumer.java:[257,9] (whitespace) WhitespaceAround: 'if' is not followed by whitespace.
5734
Error:  src/main/java/org/apache/pulsar/broker/service/Consumer.java:[258,114] (whitespace) OperatorWrap: '+' should be on a new line.
5735
Error:  src/main/java/org/apache/pulsar/broker/service/Consumer.java:[531,117] (whitespace) OperatorWrap: '+' should be on a new line.

devinbost · 2021-04-14T03:22:53Z

/pulsarbot run-failure-checks

docker/build.sh

devinbost · 2021-04-14T19:09:57Z

/pulsarbot run-failure-checks

devinbost · 2021-04-15T05:56:21Z

/pulsarbot run-failure-checks

devinbost · 2021-04-15T13:37:42Z

/pulsarbot run-failure-checks

devinbost · 2021-04-16T08:28:30Z

/pulsarbot run-failure-checks

devinbost · 2021-04-16T23:41:44Z

/pulsarbot run-failure-checks

eolivelli

LGTM

eolivelli · 2021-04-17T10:18:29Z

/pulsarbot run-failure-checks

eolivelli · 2021-04-17T10:19:07Z

@lhotari are you okay with this PR now ?
it looks like your comment has been addressed.

devinbost · 2021-04-17T16:17:38Z

/pulsarbot run-failure-checks

lhotari · 2021-04-17T16:49:20Z

/pulsarbot run-failure-checks

@devinbost please rebase your changes. The master branch contains fixes to CI issues.

…e changes to permits

devinbost · 2021-04-18T17:05:45Z

/pulsarbot run-failure-checks

devinbost · 2021-04-18T17:09:05Z

Looks like we missed a flaky test. @lhotari
org.apache.pulsar.tests.integration.io.PulsarGenericObjectSinkTest created 1 new threads
2021-04-17 20:21:28,701 - INFO - [main:FastThreadLocalCleanupListener@53] - Cleaning up FastThreadLocal thread local state.
Error: Tests run: 9, Failures: 1, Errors: 0, Skipped: 3, Time elapsed: 382.475 s <<< FAILURE! - in TestSuite
Error: testGenericObjectSink(org.apache.pulsar.tests.integration.io.PulsarGenericObjectSinkTest) Time elapsed: 47.627 s <<< FAILURE!
java.lang.AssertionError: Sink was restarted, probably an error occurred expected [true] but found [false]
at org.testng.Assert.fail(Assert.java:99)
at org.testng.Assert.failNotEquals(Assert.java:1037)
at org.testng.Assert.assertTrue(Assert.java:45)
at org.apache.pulsar.tests.integration.io.PulsarGenericObjectSinkTest.testGenericObjectSink(PulsarGenericObjectSinkTest.java:142)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
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.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)

[INFO]
[INFO] Results:
[INFO]
Error: Failures:
Error: org.apache.pulsar.tests.integration.io.PulsarGenericObjectSinkTest.testGenericObjectSink(org.apache.pulsar.tests.integration.io.PulsarGenericObjectSinkTest)
[INFO] Run 1: PASS
Error: Run 2: PulsarGenericObjectSinkTest.testGenericObjectSink:142 Sink was restarted, probably an error occurred expected [true] but found [false]

devinbost · 2021-04-18T18:58:03Z

/pulsarbot run-failure-checks

devinbost · 2021-04-18T20:22:25Z

/pulsarbot run-failure-checks

devinbost · 2021-04-19T01:48:24Z

/pulsarbot run-failure-checks

devinbost · 2021-04-19T03:53:43Z

/pulsarbot run-failure-checks

eolivelli · 2021-04-19T09:31:09Z

I am trying to cherry pick to branch-7.2 and see if it builds properly

…ges to permits (#10217)

eolivelli · 2021-04-19T09:49:43Z

@devinbost picked to branch-2.7 as c243d18

lhotari · 2021-04-19T11:34:25Z

Looks like we missed a flaky test. @lhotari
org.apache.pulsar.tests.integration.io.PulsarGenericObjectSinkTest created 1 new threads
2021-04-17 20:21:28,701 - INFO - [main:FastThreadLocalCleanupListener@53] - Cleaning up FastThreadLocal thread local state.
Error: Tests run: 9, Failures: 1, Errors: 0, Skipped: 3, Time elapsed: 382.475 s <<< FAILURE! - in TestSuite
Error: testGenericObjectSink(org.apache.pulsar.tests.integration.io.PulsarGenericObjectSinkTest) Time elapsed: 47.627 s <<< FAILURE!
java.lang.AssertionError: Sink was restarted, probably an error occurred expected [true] but found [false]

@devinbost this is fixed in #10248

sijie approved these changes Apr 13, 2021

View reviewed changes

sijie assigned devinbost Apr 13, 2021

sijie added this to the 2.8.0 milestone Apr 13, 2021

sijie added the type/enhancement The enhancements for the existing features or docs. e.g. reduce memory usage of the delayed messages label Apr 13, 2021

merlimat approved these changes Apr 13, 2021

View reviewed changes

lhotari requested changes Apr 14, 2021

View reviewed changes

docker/build.sh Outdated Show resolved Hide resolved

codelipenghui approved these changes Apr 15, 2021

View reviewed changes

eolivelli approved these changes Apr 17, 2021

View reviewed changes

Issue apache#6054 - Adding more permits debug statements to better se…

14a5c84

…e changes to permits

devinbost force-pushed the permits-logging branch from baa53fc to 14a5c84 Compare April 17, 2021 19:43

eolivelli merged commit a66dd5d into apache:master Apr 19, 2021

eolivelli added cherry-picked/branch-2.7 Archived: 2.7 is end of life release/2.7.2 labels Apr 19, 2021

eolivelli pushed a commit that referenced this pull request Apr 19, 2021

Issue #6054 - Adding more permits debug statements to better see chan…

c243d18

…ges to permits (#10217)

Adding more permits debug statements to better diagnose permit issues #10217

Adding more permits debug statements to better diagnose permit issues #10217

Uh oh!

Conversation

devinbost commented Apr 13, 2021

Uh oh!

devinbost commented Apr 13, 2021

Uh oh!

merlimat commented Apr 13, 2021

Uh oh!

devinbost commented Apr 14, 2021

Uh oh!

Uh oh!

devinbost commented Apr 14, 2021

Uh oh!

devinbost commented Apr 15, 2021

Uh oh!

devinbost commented Apr 15, 2021

Uh oh!

devinbost commented Apr 16, 2021

Uh oh!

devinbost commented Apr 16, 2021

Uh oh!

eolivelli left a comment

Choose a reason for hiding this comment

Uh oh!

eolivelli commented Apr 17, 2021

Uh oh!

eolivelli commented Apr 17, 2021

Uh oh!

devinbost commented Apr 17, 2021

Uh oh!

lhotari commented Apr 17, 2021

Uh oh!

devinbost commented Apr 18, 2021

Uh oh!

devinbost commented Apr 18, 2021

Uh oh!

devinbost commented Apr 18, 2021

Uh oh!

devinbost commented Apr 18, 2021

Uh oh!

devinbost commented Apr 19, 2021

Uh oh!

devinbost commented Apr 19, 2021

Uh oh!

eolivelli commented Apr 19, 2021

Uh oh!

eolivelli commented Apr 19, 2021

Uh oh!

lhotari commented Apr 19, 2021

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

6 participants