Cursor recover took extreme long time
- Dominant language
- Java
- Stars
- 15.3k
- Forks
- 3.8k
- Avg merge
- 1d 14h
- Merged PRs (30d)
- 160
Description
**Describe the bug**
In our production, after a node restart, a topic partition keeping load timed out:
```
2022-04-26T21:39:30.444Z ERROR [pulsar-io-4-16] org.apache.pulsar.broker.service.ServerCnx - [/10.xxx:56961] Failed to create topic persistent://data/uu/feature.plain.result.queue-partition-31, producerId=31
java.util.concurrent.CompletionException: org.apache.pulsar.common.util.FutureUtil$LowOverheadTimeoutException: Failed to load topic within timeout
at java.util.concurrent.CompletableFuture.encodeThrowable(CompletableFuture.java:292)
at java.util.concurrent.CompletableFuture.completeThrowable(CompletableFuture.java:308)
at java.util.concurrent.CompletableFuture.uniCompose(CompletableFuture.java:943)
at java.util.concurrent.CompletableFuture$UniCompose.tryFire(CompletableFuture.java:926)
at java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:474)
at java.util.concurrent.CompletableFuture.completeExceptionally(CompletableFuture.java:1977)
at org.apache.pulsar.common.util.FutureUtil.lambda$addTimeoutHandling$1(FutureUtil.java:141)
at io.netty.util.concurrent.PromiseTask.runTask(PromiseTask.java:98)
at io.netty.util.concurrent.ScheduledFutureTask.run(ScheduledFutureTask.java:170)
at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:164)
at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:469)
at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:384)
at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:986)
at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
at java.lang.Thread.run(Thread.java:748)
Caused by: org.apache.pulsar.common.util.FutureUtil$LowOverheadTimeoutException: Failed to load topic within timeout
at org.apache.pulsar.broker.service.BrokerService.futureWithDeadline(...)(Unknown Source)
```
The log shows there's one cursor recovery didn't callback, it seems cursor's ledger recover took very long time:
```
2022-04-26T21:38:30.533Z INFO [bookkeeper-ml-scheduler-OrderedScheduler-4-0] org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl - [data/uu/persistent/feature.plain.result.queue-partition-31] Loading cursor data.feature.c.user.deliver.and.chat.features.to.hbase
2022-04-26T21:38:30.533Z INFO [bookkeeper-ml-scheduler-OrderedScheduler-4-0] org.apache.bookkeeper.mledger.impl.ManagedCursorImpl - [data/uu/persistent/feature.plain.result.queue-partition-31] Recovering from bookkeeper ledger cursor: data.feature.c.user.deliver.and.chat.features.to.hbase
2022-04-26T21:38:30.539Z INFO [bookkeeper-ml-scheduler-OrderedScheduler-4-0] org.apache.bookkeeper.mledger.impl.ManagedCursorImpl - [data/uu/persistent/feature.plain.result.queue-partition-31] Consumer data.feature.c.user.deliver.and.chat.features.to.hbase meta-data recover from ledger 110091138
2022-04-26T21:39:30.560Z INFO [bookkeeper-ml-scheduler-OrderedScheduler-4-0] org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl - [data/uu/persistent/feature.plain.result.queue-partition-31] Loading cursor data.feature.c.user.deliver.and.chat.features.to.hbase
2022-04-26T21:39:30.560Z INFO [bookkeeper-ml-scheduler-OrderedScheduler-4-0] org.apache.bookkeeper.mledger.impl.ManagedCursorImpl - [data/uu/persistent/feature.plain.result.queue-partition-31] Recovering from bookkeeper ledger cursor: data.feature.c.user.deliver.and.chat.features.to.hbase
2022-04-26T21:39:30.561Z INFO [bookkeeper-ml-scheduler-OrderedScheduler-4-0] org.apache.bookkeeper.mledger.impl.ManagedCursorImpl - [data/uu/persistent/feature.plain.result.queue-partition-31] Consumer data.feature.c.user.deliver.and.chat.features.to.hbase meta-data recover from ledger 110091138
2022-04-26T21:40:30.667Z INFO [bookkeeper-ml-scheduler-OrderedScheduler-4-0] org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl - [data/uu/persistent/feature.plain.result.queue-partition-31] Loading cursor data.feature.c.user.deliver.and.chat.features.to.hbase
2022-04-26T21:40:30.667Z INFO [bookkeeper-ml-scheduler-OrderedScheduler-4-0] org.apache.bookkeeper.mledger.impl.ManagedCursorImpl - [data/uu/persistent/feature.plain.result.queue-partition-31] Recovering from bookkeeper ledger cursor: data.feature.c.user.deliver.and.chat.features.to.hbase
2022-04-26T21:40:30.668Z INFO [bookkeeper-ml-scheduler-OrderedScheduler-4-0] org.apache.bookkeeper.mledger.impl.ManagedCursorImpl - [data/uu/persistent/feature.plain.result.queue-partition-31] Consumer data.feature.c.user.deliver.and.chat.features.to.hbase meta-data recover from ledger 110091138
2022-04-26T21:41:30.773Z INFO [bookkeeper-ml-scheduler-OrderedScheduler-4-0] org.apache.bookkeeper.mledger.impl.ManagedCursorImpl - [data/uu/persistent/feature.plain.result.queue-partition-31] Consumer data.feature.c.user.deliver.and.chat.features.to.hbase meta-data recover from ledger 110091138
2022-04-26T21:41:30.773Z INFO [bookkeeper-ml-scheduler-OrderedScheduler-4-0] org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl - [data/uu/persistent/feature.plain.result.queue-partition-31] Loading cursor data.feature.c.user.deliver.and.chat.features.to.hbase
2022-04-26T21:41:30.773Z INFO [bookkeeper-ml-scheduler-OrderedScheduler-4-0] org.apache.bookkeeper.mledger.impl.ManagedCursorImpl - [data/uu/persistent/feature.plain.result.queue-partition-31] Recovering from bookkeeper ledger cursor: data.feature.c.user.deliver.and.chat.features.to.hbase
2022-04-26T21:42:30.888Z INFO [bookkeeper-ml-scheduler-OrderedScheduler-4-0] org.apache.bookkeeper.mledger.impl.ManagedCursorImpl - [data/uu/persistent/feature.plain.result.queue-partition-31] Recovering from bookkeeper ledger cursor: data.feature.c.user.deliver.and.chat.features.to.hbase
2022-04-26T21:42:30.888Z INFO [bookkeeper-ml-scheduler-OrderedScheduler-4-0] org.apache.bookkeeper.mledger.impl.ManagedCursorImpl - [data/uu/persistent/feature.plain.result.queue-partition-31] Consumer data.feature.c.user.deliver.and.chat.features.to.hbase meta-data recover from ledger 110091138
2022-04-26T21:42:30.888Z INFO [bookkeeper-ml-scheduler-OrderedScheduler-4-0] org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl - [data/uu/persistent/feature.plain.result.queue-partition-31] Loading cursor data.feature.c.user.deliver.and.chat.features.to.hbase
2022-04-26T21:43:31.106Z INFO [bookkeeper-ml-scheduler-OrderedScheduler-4-0] org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl - [data/uu/persistent/feature.plain.result.queue-partition-31] Loading cursor data.feature.c.user.deliver.and.chat.features.to.hbase
2022-04-26T21:43:31.106Z INFO [bookkeeper-ml-scheduler-OrderedScheduler-4-0] org.apache.bookkeeper.mledger.impl.ManagedCursorImpl - [data/uu/persistent/feature.plain.result.queue-partition-31] Recovering from bookkeeper ledger cursor: data.feature.c.user.deliver.and.chat.features.to.hbase
2022-04-26T21:43:31.106Z INFO [bookkeeper-ml-scheduler-OrderedScheduler-4-0] org.apache.bookkeeper.mledger.impl.ManagedCursorImpl - [data/uu/persistent/feature.plain.result.queue-partition-31] Consumer data.feature.c.user.deliver.and.chat.features.to.hbase meta-data recover from ledger 110091138
2022-04-26T21:44:31.391Z INFO [bookkeeper-ml-scheduler-OrderedScheduler-4-0] org.apache.bookkeeper.mledger.impl.ManagedCursorImpl - [data/uu/persistent/feature.plain.result.queue-partition-31] Recovering from bookkeeper ledger cursor: data.feature.c.user.deliver.and.chat.features.to.hbase
2022-04-26T21:44:31.391Z INFO [bookkeeper-ml-scheduler-OrderedScheduler-4-0] org.apache.bookkeeper.mledger.impl.ManagedCursorImpl - [data/uu/persistent/feature.plain.result.queue-partition-31] Consumer data.feature.c.user.deliver.and.chat.features.to.hbase meta-data recover from ledger 110091138
2022-04-26T21:44:31.391Z INFO [bookkeeper-ml-scheduler-OrderedScheduler-4-0] org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl - [data/uu/persistent/feature.plain.result.queue-partition-31] Loading cursor data.feature.c.user.deliver.and.chat.features.to.hbase
```
And it will start a new recover op after `managedLedgerMetadataOperationsTimeoutSeconds`, so bookie keep logging `Ledger fence request received for ledger`:

After near 27h, the recover op finally callback (Actually the topic has been moved to another node in this moment):
```
2022-04-28T00:25:36.147Z INFO [BookKeeperClientWorker-OrderedExecutor-2-0] org.apache.bookkeeper.mledger.impl.ManagedCursorImpl - [data/uu/persistent/feature.plain.result.queue-partition-31] Opened ledger 110091138 for consumer data.feature.c.user.deliver.and.chat.features.to.hbase. rc=0
2022-04-28T00:25:36.163Z INFO [BookKeeperClientWorker-OrderedExecutor-2-0] org.apache.bookkeeper.mledger.impl.ManagedCursorImpl - [data/uu/persistent/feature.plain.result.queue-partition-31] Opened ledger 110091138 for consumer data.feature.c.user.deliver.and.chat.features.to.hbase. rc=0
2022-04-28T00:25:36.163Z INFO [BookKeeperClientWorker-OrderedExecutor-2-0] org.apache.bookkeeper.mledger.impl.ManagedCursorImpl - [data/uu/persistent/feature.plain.result.queue-partition-31] Opened ledger 110091138 for consumer data.feature.c.user.deliver.and.chat.features.to.hbase. rc=0
2022-04-28T00:25:36.172Z INFO [BookKeeperClientWorker-OrderedExecutor-2-0] org.apache.bookkeeper.mledger.impl.ManagedCursorImpl - [data/uu/persistent/feature.plain.result.queue-partition-31] Cursor data.feature.c.user.deliver.and.chat.features.to.hbase recovered to position 110398886:151969
2022-04-28T00:25:36.173Z INFO [BookKeeperClientWorker-OrderedExecutor-2-0] org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl - [data/uu/persistent/feature.plain.result.queue-partition-31] Recovery for cursor data.feature.c.user.deliver.and.chat.features.to.hbase completed. pos=110398886:151969 -- todo=0
2022-04-28T00:25:36.188Z INFO [BookKeeperClientWorker-OrderedExecutor-2-0] org.apache.bookkeeper.mledger.impl.ManagedCursorImpl - [data/uu/persistent/feature.plain.result.queue-partition-31] Cursor data.feature.c.user.deliver.and.chat.features.to.hbase recovered to position 110398886:151969
2022-04-28T00:25:36.188Z INFO [BookKeeperClientWorker-OrderedExecutor-2-0] org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl - [data/uu/persistent/feature.plain.result.queue-partition-31] Recovery for cursor data.feature.c.user.deliver.and.chat.features.to.hbase completed. pos=110398886:151969 -- todo=0
2022-04-28T00:25:36.189Z INFO [BookKeeperClientWorker-OrderedExecutor-2-0] org.apache.bookkeeper.mledger.impl.ManagedCursorImpl - [data/uu/persistent/feature.plain.result.queue-partition-31] Cursor data.feature.c.user.deliver.and.chat.features.to.hbase recovered to position 110398886:151969
2022-04-28T00:25:36.189Z INFO [BookKeeperClientWorker-OrderedExecutor-2-0] org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl - [data/uu/persistent/feature.plain.result.queue-partition-31] Recovery for cursor data.feature.c.user.deliver.and.chat.features.to.hbase completed. pos=110398886:151969 -- todo=0
2022-04-28T00:25:36.479Z INFO [BookKeeperClientWorker-OrderedExecutor-2-0] org.apache.bookkeeper.mledger.impl.ManagedCursorImpl - [data/uu/persistent/feature.plain.result.queue-partition-31] Opened ledger 110091138 for consumer data.feature.c.user.deliver.and.chat.features.to.hbase. rc=0
2022-04-28T00:25:36.480Z INFO [BookKeeperClientWorker-OrderedExecutor-2-0] org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl - [data/uu/persistent/feature.plain.result.queue-partition-31] Recovery for cursor data.feature.c.user.deliver.and.chat.features.to.hbase completed. pos=110398886:151969 -- todo=0
2022-04-28T00:25:36.480Z INFO [BookKeeperClientWorker-OrderedExecutor-2-0] org.apache.bookkeeper.mledger.impl.ManagedCursorImpl - [data/uu/persistent/feature.plain.result.queue-partition-31] Cursor data.feature.c.user.deliver.and.chat.features.to.hbase recovered to position 110398886:151969
2022-04-28T00:25:36.487Z INFO [BookKeeperClientWorker-OrderedExecutor-2-0] org.apache.bookkeeper.mledger.impl.ManagedCursorImpl - [data/uu/persistent/feature.plain.result.queue-partition-31] Opened ledger 110091138 for consumer data.feature.c.user.deliver.and.chat.features.to.hbase. rc=0
2022-04-28T00:25:36.487Z INFO [BookKeeperClientWorker-OrderedExecutor-2-0] org.apache.bookkeeper.mledger.impl.ManagedCursorImpl - [data/uu/persistent/feature.plain.result.queue-partition-31] Opened ledger 110091138 for consumer data.feature.c.user.deliver.and.chat.features.to.hbase. rc=0
2022-04-28T00:25:36.487Z INFO [BookKeeperClientWorker-OrderedExecutor-2-0] org.apache.bookkeeper.mledger.impl.ManagedCursorImpl - [data/uu/persistent/feature.plain.result.queue-partition-31] Opened ledger 110091138 for consumer data.feature.c.user.deliver.and.chat.features.to.hbase. rc=0
2022-04-28T00:25:36.487Z INFO [BookKeeperClientWorker-OrderedExecutor-2-0] org.apache.bookkeeper.mledger.impl.ManagedCursorImpl - [data/uu/persistent/feature.plain.result.queue-partition-31] Opened ledger 110091138 for consumer data.feature.c.user.deliver.and.chat.features.to.hbase. rc=0
2022-04-28T00:25:36.487Z INFO [BookKeeperClientWorker-OrderedExecutor-2-0] org.apache.bookkeeper.mledger.impl.ManagedCursorImpl - [data/uu/persistent/feature.plain.result.queue-partition-31] Opened ledger 110091138 for consumer data.feature.c.user.deliver.and.chat.features.to.hbase. rc=0
2022-04-28T00:25:36.487Z INFO [BookKeeperClientWorker-OrderedExecutor-2-0] org.apache.bookkeeper.mledger.impl.ManagedCursorImpl - [data/uu/persistent/feature.plain.result.queue-partition-31] Opened ledger 110091138 for consumer data.feature.c.user.deliver.and.chat.features.to.hbase. rc=0
2022-04-28T00:25:36.489Z INFO [BookKeeperClientWorker-OrderedExecutor-2-0] org.apache.bookkeeper.mledger.impl.ManagedCursorImpl - [data/uu/persistent/feature.plain.result.queue-partition-31] Opened ledger 110091138 for consumer data.feature.c.user.deliver.and.chat.features.to.hbase. rc=0
2022-04-28T00:25:36.489Z INFO [BookKeeperClientWorker-OrderedExecutor-2-0] org.apache.bookkeeper.mledger.impl.ManagedCursorImpl - [data/uu/persistent/feature.plain.result.queue-partition-31] Opened ledger 110091138 for consumer data.feature.c.user.deliver.and.chat.features.to.hbase. rc=0
```
**Additional context**
- OS: `3.10.0-1160.53.1.el7.x86_64`
- java: `1.8.0_181`
- pulsar: `2.8.3`
Contributor guide
Research direction
Start by tracing cursor recovery through ManagedCursorImpl and ManagedLedgerImpl, then inspect how FutureUtil timeouts are handled during ledger recovery. Use the reported recovery and broker timeout logs to understand the repeated operations; the issue does not define a specific acceptance test or expected fix.
Written by the indexing model from the issue text.
Assessment
- Tech stack
- java
- Domain
- distributed-systems
- Issue type
- Bug
- Difficulty
- 5/5
- Estimated time
- Over a week
- Activity status
- Stale
- Clarity
- Needs clarification
- Newbie friendliness
- 25/100