fightBoxing commented on issue #4172:
URL: https://github.com/apache/amoro/issues/4172#issuecomment-4318443862
### Reproduced & root-caused — details below
I managed to reproduce this in our env and captured the full stack trace.
Sharing the analysis so we can align on a fix direction.
---
#### 1. What we observed
Thrift server log (AMS side) when the process got stuck in `RUNNING`:
```
ERROR [thrift-server-optimize-manager-92301]
o.a.a.s.u.t.ThriftServiceMetricsHandler
Thrift service:DefaultOptimizingService.completeTask execute failed.
org.apache.ibatis.exceptions.PersistenceException:
### Error updating database.
Cause: com.mysql.cj.jdbc.exceptions.MySQLTransactionRollbackException:
Lock wait timeout exceeded; try restarting transaction
### The error may exist in file [.../mapper/TableMetaMapper.java]
### updateTableRuntime-Inline
### SQL: UPDATE table_runtime SET current_snapshot_id = ?,
current_change_snapshotId = ?,
last_optimized_snapshotId = ?, last_optimized_change_snapshotId = ?,
last_major_optimizing_time = ?, last_full_optimizing_time = ?,
last_minor_optimizing_time = ?, optimizing_status_code = ?,
optimizing_status_start_time = ?, optimizing_process_id = ?,
pending_input = ?, table_config = ? WHERE table_id = ?
```
Stack trace (trimmed to the essential frames):
```
at TableRuntime.persistUpdatingRuntime(TableRuntime.java:451)
at TableRuntime.lambda$beginCommitting$6(TableRuntime.java:243)
at StatedPersistentBase.invokeConsistency(StatedPersistentBase.java:47)
at TableRuntime.beginCommitting(TableRuntime.java:238)
at
OptimizingQueue$TableOptimizingProcess.acceptResult(OptimizingQueue.java:458)
at TaskRuntime.lambda$complete$0(TaskRuntime.java:80)
at StatedPersistentBase.invokeConsistency(StatedPersistentBase.java:47)
at TaskRuntime.complete(TaskRuntime.java:...)
at DefaultOptimizingService.completeTask(DefaultOptimizingService.java:...)
```
After this exception the state stayed:
- DB `optimizing_process.status = RUNNING`
- All `task_runtime.status = SUCCESS` (or `ACKED` for the last one that got
rolled back)
- Table `optimizing_status_code` still `*_OPTIMIZING`, **not** `COMMITTING`
- Only recovery path: nothing periodic — a full AMS restart is required so
the `reload()` path kicks in.
---
#### 2. Why the process hangs — root cause
The failing SQL is the `UPDATE table_runtime` issued by
`TableRuntime#beginCommitting()` to flip `optimizing_status_code` to
`COMMITTING`. It's triggered from inside the outer `TaskRuntime#complete`
transaction:
```
DefaultOptimizingService.completeTask
└─ TaskRuntime.complete (invokeConsistency #1,
wraps a transaction)
├─ statusMachine.accept(SUCCESS) // in-memory task ->
SUCCESS
├─ persistTaskRuntime() // DB task -> SUCCESS
└─ owner.acceptResult(this) // TaskRuntime.java:80
└─ OptimizingQueue.acceptResult // OptimizingQueue.java:438
└─ tableRuntime.beginCommitting() // OptimizingQueue.java:458
└─ TableRuntime.beginCommitting // TableRuntime.java:238
└─ persistUpdatingRuntime() // TableRuntime.java:451
❌ Lock wait timeout
```
When `persistUpdatingRuntime()` throws, the outer `invokeConsistency` in
`StatedPersistentBase` does this:
```java
// StatedPersistentBase.java:47
protected final void invokeConsistency(Runnable runnable) {
stateLock.lock();
Map<Field, Object> states = retainStates();
try {
doAsTransaction(runnable);
} catch (Throwable throwable) {
restoreStates(states); // <-- rolls back @StateField ON THE CURRENT
OBJECT ONLY
throw throwable;
} finally {
stateLock.unlock();
}
}
```
`restoreStates()` uses reflection and only touches fields annotated with
`@StateField` **on the `TaskRuntime` instance** that started the transaction.
That gives us this asymmetric rollback:
| State | Rolled back? | Result |
|---|---|---|
| `TaskRuntime.status` (SUCCESS → ACKED) | ✅ via `restoreStates` | task
looks "unfinished" in memory |
| DB row in `task_runtime` | ✅ `doAsTransaction` rolls it back | consistent
with memory |
| DB row in `table_runtime` (`optimizing_status_code`) | ❌ the UPDATE itself
failed | stays `*_OPTIMIZING` |
| `OptimizingProcess.status` (RUNNING) | ❌ not a `@StateField` of
`TaskRuntime` | stays `RUNNING` forever |
So from the optimizer's perspective the `completeTask` RPC failed; but the
task output has already been written to storage, and the optimizer typically
won't *re-execute* the same rewrite task — it just gives up on that RPC.
Nothing on AMS side then re-drives `beginCommitting()`, and the process stays
`RUNNING` indefinitely.
---
#### 3. Why it's `Lock wait timeout` specifically
`table_runtime` is a hot single-row record: every status transition
(`beginCommitting`, `refresh`, `persistPendingInput`, quota updates…) all goes
through `persistUpdatingRuntime()` → the same `UPDATE ... WHERE table_id = ?`.
When another writer (e.g. `TableRuntimeRefreshExecutor`) holds the row lock,
the default `innodb_lock_wait_timeout` (50s) trips and InnoDB rolls the
`beginCommitting` transaction back.
This is **not a rare race** — it's a predictable collision under load.
---
#### 4. Existing evidence in the tree
The test
`TestDefaultOptimizingService#testReloadAllTasksCompletedNotYetCommitting`
already describes exactly this situation:
> Simulate: AMS crashes after persisting the last task as SUCCESS but before
`beginCommitting()` updates the table status to COMMITTING.
> DB state: process=RUNNING, all tasks=SUCCESS, table=\*\_OPTIMIZING
That test verifies recovery **only when AMS restarts** and `reload()` runs.
Issue #4172 is the same state — but without a restart nothing drives recovery.
---
#### 5. Suggested fix directions
**A. Periodic self-heal (lowest risk, recommended)**
Extend the `reload()` recovery rule ("if all tasks succeeded but table is
not `COMMITTING`, call `beginCommitting()`") into the periodic
`TableRuntimeRefreshExecutor`. Needs to be idempotent and re-check
`allTasksPrepared()` under the process lock.
**B. Bounded retry + decoupling**
Don't let `beginCommitting()` run inside the `TaskRuntime` transaction.
After persisting the task as SUCCESS, attempt `beginCommitting()` with a small
bounded retry (e.g. 3× with backoff) to absorb lock-wait blips; on exhaustion,
record a pending flag and rely on (A) to finish the job.
**C. Symmetric rollback**
If `beginCommitting()` fails, explicitly revert the task back to `ACKED` and
surface an error that the optimizer *will* retry as `completeTask`. Downside:
current optimizer retry semantics don't guarantee a re-`completeTask` on the
same task result.
I'd suggest pairing **A** (correctness backstop) with **B** (fast path),
since (A) alone also covers other future failure paths into the same hang state.
Happy to put up a PR — planning to start with option A since it reuses the
existing, tested recovery logic. Let me know if any maintainer prefers a
different direction before I start.
--
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]
