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/02/28 06:32:00 UTC
[GitHub] [pulsar] mattisonchao opened a new pull request #14486: [Broker] Fix many stack trace logs when concurrent mark delete.
mattisonchao opened a new pull request #14486:
URL: https://github.com/apache/pulsar/pull/14486
### Motivation
I found a lot of stack trace logs when I use 25k consumers to consume messages.
```java
2022-02-28T05:06:25,472+0000 [bookkeeper-ml-scheduler-OrderedScheduler-0-0] WARN org.apache.bookkeeper.mledger.impl.ManagedCursorImpl - [public/default/persistent/bench%252F24412][ip-10-0-0-132_bench_sub_24412_880606346] Failed to flush mark-delete position
org.apache.bookkeeper.mledger.ManagedLedgerException: java.lang.IllegalArgumentException: Mark deleting an already mark-deleted position
Caused by: java.lang.IllegalArgumentException: Mark deleting an already mark-deleted position
at org.apache.bookkeeper.mledger.impl.ManagedCursorImpl.setAcknowledgedPosition(ManagedCursorImpl.java:1580) ~[org.apache.pulsar-managed-ledger-2.9.1.jar:2.9.1]
at org.apache.bookkeeper.mledger.impl.ManagedCursorImpl.asyncMarkDelete(ManagedCursorImpl.java:1718) ~[org.apache.pulsar-managed-ledger-2.9.1.jar:2.9.1]
at org.apache.bookkeeper.mledger.impl.ManagedCursorImpl.flush(ManagedCursorImpl.java:3020) ~[org.apache.pulsar-managed-ledger-2.9.1.jar:2.9.1]
at org.apache.bookkeeper.mledger.impl.ManagedLedgerFactoryImpl.lambda$flushCursors$1(ManagedLedgerFactoryImpl.java:232) ~[org.apache.pulsar-managed-ledger-2.9.1.jar:2.9.1]
at java.lang.Iterable.forEach(Iterable.java:75) ~[?:?]
at org.apache.bookkeeper.mledger.impl.ManagedLedgerFactoryImpl.lambda$flushCursors$2(ManagedLedgerFactoryImpl.java:232) ~[org.apache.pulsar-managed-ledger-2.9.1.jar:2.9.1]
at java.util.concurrent.ConcurrentHashMap$ValuesView.forEach(ConcurrentHashMap.java:4772) ~[?:?]
at org.apache.bookkeeper.mledger.impl.ManagedLedgerFactoryImpl.flushCursors(ManagedLedgerFactoryImpl.java:228) ~[org.apache.pulsar-managed-ledger-2.9.1.jar:2.9.1]
at org.apache.pulsar.common.util.Runnables$CatchingAndLoggingRunnable.run(Runnables.java:53) [org.apache.pulsar-pulsar-common-2.9.1.jar:2.9.1]
at org.apache.bookkeeper.common.util.OrderedExecutor$TimedRunnable.run(OrderedExecutor.java:203) [org.apache.bookkeeper-bookkeeper-common-4.14.2.jar:4.14.2]
at org.apache.bookkeeper.common.util.OrderedExecutor$TimedRunnable.run(OrderedExecutor.java:203) [org.apache.bookkeeper-bookkeeper-common-4.14.2.jar:4.14.2]
at com.google.common.util.concurrent.MoreExecutors$ScheduledListeningDecorator$NeverSuccessfulListenableFutureTask.run(MoreExecutors.java:705) [com.google.guava-guava-30.1-jre.jar:?]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) [?:?]
at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:305) [?:?]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305) [?:?]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) [io.netty-netty-common-4.1.72.Final.jar:4.1.72.Final]
at java.lang.Thread.run(Thread.java:829) [?:?]
```
I think the problem is caused by ``ManagedCursorImpl#setAcknowledgedPosition`` being called in a concurrent environment.
### Modifications
- Logging with debug level failed because the marker location was already marked for deletion.
### Verifying this change
- [x] Make sure that the change passes the CI checks.
### Documentation
- [x] `no-need-doc`
--
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] mattisonchao commented on a change in pull request #14486: [WIP][Broker] Fix many stack trace logs when concurrent mark delete.
Posted by GitBox <gi...@apache.org>.
mattisonchao commented on a change in pull request #14486:
URL: https://github.com/apache/pulsar/pull/14486#discussion_r815731097
##########
File path: managed-ledger/src/main/java/org/apache/bookkeeper/mledger/impl/ManagedCursorImpl.java
##########
@@ -3051,7 +3051,15 @@ public void markDeleteComplete(Object ctx) {
@Override
public void markDeleteFailed(ManagedLedgerException exception, Object ctx) {
- log.warn("[{}][{}] Failed to flush mark-delete position", ledger.getName(), name, exception);
+ //They throw an IllegalArgumentException when the mark deletes a position that has already been deleted.
+ //See this#setAcknowledgedPosition
+ if (exception.getCause() instanceof IllegalArgumentException) {
Review comment:
@Technoboy-
I think we need to find all the logic about this and reconsider if we need to throw an exception.
--
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] mattisonchao commented on pull request #14486: [Broker] Fix many stack trace logs when concurrent mark delete.
Posted by GitBox <gi...@apache.org>.
mattisonchao commented on pull request #14486:
URL: https://github.com/apache/pulsar/pull/14486#issuecomment-1053935389
I checked the code and it looks like the consumer acknowledgement and cursor flush tasks are conflicting. but I'm not sure about that, please help me to check the root reason.
Very thanks~
--
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] mattisonchao closed pull request #14486: [WIP][Broker] Fix many stack trace logs when concurrent mark delete.
Posted by GitBox <gi...@apache.org>.
mattisonchao closed pull request #14486:
URL: https://github.com/apache/pulsar/pull/14486
--
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] Technoboy- commented on a change in pull request #14486: [WIP][Broker] Fix many stack trace logs when concurrent mark delete.
Posted by GitBox <gi...@apache.org>.
Technoboy- commented on a change in pull request #14486:
URL: https://github.com/apache/pulsar/pull/14486#discussion_r815716291
##########
File path: managed-ledger/src/main/java/org/apache/bookkeeper/mledger/impl/ManagedCursorImpl.java
##########
@@ -3051,7 +3051,15 @@ public void markDeleteComplete(Object ctx) {
@Override
public void markDeleteFailed(ManagedLedgerException exception, Object ctx) {
- log.warn("[{}][{}] Failed to flush mark-delete position", ledger.getName(), name, exception);
+ //They throw an IllegalArgumentException when the mark deletes a position that has already been deleted.
+ //See this#setAcknowledgedPosition
+ if (exception.getCause() instanceof IllegalArgumentException) {
Review comment:
For ManagedCursorImpl#setAcknowledgedPosition, could we add a new exception :
```
if (newMarkDeletePosition.compareTo(markDeletePosition) < 0) {
throw new AlreadySetMarkDeleteException("Mark deleting an already mark-deleted position");
}
```
or print log here?
```
if (newMarkDeletePosition.compareTo(markDeletePosition) < 0) {
log.warn("Mark deleting an already mark-deleted position : {}", newMarkDeletePosition);
return markDeletePosition;
}
```
@mattisonchao @codelipenghui @merlimat
--
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] mattisonchao edited a comment on pull request #14486: [WIP][Broker] Fix many stack trace logs when concurrent mark delete.
Posted by GitBox <gi...@apache.org>.
mattisonchao edited a comment on pull request #14486:
URL: https://github.com/apache/pulsar/pull/14486#issuecomment-1054140537
> @mattisonchao Might relate to the backlog eviction? or the message TTL?
I think this is because we have 25k consumers constantly acknowledging messages and then calling ``ManagedCursorImpl#setAcknowledgedPosition`` and we have another timed task which also calls it to refresh the cursor position.
https://github.com/apache/pulsar/blob/3da048c8a6df7404df4e6c3301370feb96c6c14b/managed-ledger/src/main/java/org/apache/bookkeeper/mledger/impl/ManagedLedgerFactoryImpl.java#L193-L194
There may be times when both ack and schedule flush positions at the same time, which will cause a checked exception to be thrown.
--
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] mattisonchao closed pull request #14486: [WIP][Broker] Fix many stack trace logs when concurrent mark delete.
Posted by GitBox <gi...@apache.org>.
mattisonchao closed pull request #14486:
URL: https://github.com/apache/pulsar/pull/14486
--
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] mattisonchao edited a comment on pull request #14486: [WIP][Broker] Fix many stack trace logs when concurrent mark delete.
Posted by GitBox <gi...@apache.org>.
mattisonchao edited a comment on pull request #14486:
URL: https://github.com/apache/pulsar/pull/14486#issuecomment-1054140537
--
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] mattisonchao commented on pull request #14486: [WIP][Broker] Fix many stack trace logs when concurrent mark delete.
Posted by GitBox <gi...@apache.org>.
mattisonchao commented on pull request #14486:
URL: https://github.com/apache/pulsar/pull/14486#issuecomment-1054140537
> @mattisonchao Might relate to the backlog eviction? or the message TTL?
I think this is because we have 25k consumers constantly acknowledging messages and then calling ``ManagedCursorImpl#setAcknowledgedPosition`` and we have another timed task ```` which also calls it to refresh the cursor position.
There may be a point in time when ack and schedule flush the position at the same time, which will cause a check exception to be thrown.
--
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 pull request #14486: [Broker] Fix many stack trace logs when concurrent mark delete.
Posted by GitBox <gi...@apache.org>.
codelipenghui commented on pull request #14486:
URL: https://github.com/apache/pulsar/pull/14486#issuecomment-1054015732
@mattisonchao Might relate to the backlog eviction? or the message TTL?
--
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