[AMORO-4235] Recognize stale optimizer responses on the AMS side#4261
[AMORO-4235] Recognize stale optimizer responses on the AMS side#4261j1wonpark wants to merge 7 commits into
Conversation
When the OptimizerKeeper (or resetStaleTasksForThread on re-poll) resets a task that is still executing, the optimizer's in-flight ack/complete arrives after the task's token has been cleared. TaskRuntime.validThread then threw "Task has been reset or not yet scheduled", surfacing as an ERROR; for completion it also broke the SCHEDULED -> SUCCESS transition (IllegalTaskStateException). The AMS now recognizes stale responses by (token, threadId, status): - ack: rejected outside the transaction so the optimizer skips the obsolete round, without the misleading "failed to commit transaction" error. - complete: ignored gracefully, since the reported run belongs to a torn-down round. This fixes the rejection of valid optimizer responses. The permanent-stuck / uncancelable symptom in the issue could not be reproduced from the excerpt logs and may need the full log to confirm -- hence "Relates to" rather than "Close". Tests: - TestOptimizingQueue: unit reproductions via the pollTask path (multi-task stale ack, single-task stale completion). - TestDefaultOptimizingService: end-to-end reproduction driving the real OptimizerKeeper ack-timeout reset of a live optimizer's task. Relates to apache#4235 Signed-off-by: Jiwon Park <jpark92@outlook.kr>
Completing a task before ack now produces no exception (the AMS absorbs it as a stale response, indistinguishable from a completion for a task reset and re-scheduled to the same thread), so assert the task stays SCHEDULED instead of expecting IllegalTaskStateException. Signed-off-by: Jiwon Park <jpark92@outlook.kr>
Signed-off-by: Jiwon Park <jpark92@outlook.kr>
| // to a round that the OptimizerKeeper has already torn down. Absorb it gracefully instead of | ||
| // failing the (now illegal) state transition; the task will be re-executed in its current | ||
| // round. | ||
| if (isStaleResponse(thread) || status != Status.ACKED) { |
There was a problem hiding this comment.
TaskRuntime.complete only ignores a completion when isStaleResponse(thread) || status != ACKED. If the old round’s completeTask RPC is delayed until the same task has already gone through SCHEDULED -> ACKED again on the same optimizer thread, then token, threadId, and status all match. The old completion will pass the current check and be applied as the result of the new round.
There was a problem hiding this comment.
Thanks for the careful review — that's a sharp observation, and you're right. When the same task is re-scheduled to the same optimizer thread, schedule() re-assigns the identical token/threadId, so (token, threadId, status) has no way to tell a delayed completion of the previous round apart from the current one.
For context on how I ended up leaving this window as-is in this PR: the behavior is the same before and after this change. The removed validThread relied on the same (token, threadId) key, and the state machine already accepted a thread-matching completion only at ACKED — so the pre-existing code accepted the same delayed completion in exactly the same window. This PR changes how the surrounding cases fail (graceful reject/ignore instead of a transaction error), but does not widen what gets accepted.
Closing the window completely would need a per-attempt discriminator that the optimizer echoes back (e.g. an attempt id carried via the existing OptimizingTask.properties / OptimizingTaskResult.summary maps, compared in complete()), which requires changes on the optimizer client side as well. Since this PR doesn't change what gets accepted, I'd prefer to keep that improvement out of its scope and keep this PR focused on handling the stale responses gracefully on the AMS side.
|
|
||
| // ack-timeout is 30s; the optimizer stays alive (Toucher touches every 300ms), so this hits the | ||
| // SCHEDULED + ackTimeout branch rather than the optimizer-expired branch. | ||
| Thread.sleep(35000); |
There was a problem hiding this comment.
on the default 30-second ack timeout and then sleeps for 35 seconds. This adds a large fixed delay to the test suite and can still be brittle under slow or noisy CI environments.
Suggested fix: reduce optimizer.task-ack-timeout for this test to a small test-only value, such as 1-2 seconds, and wait for the task status with polling/await logic instead of a fixed 35-second sleep.
There was a problem hiding this comment.
Good point, fixed in 515be61. OPTIMIZER_TASK_ACK_TIMEOUT is now overridden in AMSServiceTestBase and the fixed 35s sleep is replaced with a 100ms status-polling wait, so the test finishes right after the keeper reset lands (~6s instead of 35s).
One finding from trying the suggested 1-2s value: the ack timeout has to stay above optimizer.polling-timeout (3s). A pollTask blocking for its full polling timeout would otherwise pick up the very task the keeper reset by ack-timeout in the meantime — at 2s this broke testPollTaskThreeTimes, whose final poll expects null. So I settled on 5s and left a comment in AMSServiceTestBase documenting the constraint.
…eeping 35s Address review feedback: testAckTimeoutResetThenLateAckRejected relied on the default 30s optimizer.task-ack-timeout and a fixed Thread.sleep(35000). - Override OPTIMIZER_TASK_ACK_TIMEOUT to 5s in AMSServiceTestBase. It must stay above optimizer.polling-timeout (3s): a blocking pollTask waiting out its full timeout would otherwise pick up the task the keeper reset by ack-timeout in the meantime (this broke testPollTaskThreeTimes at 2s). - Replace the fixed sleep with waitForTaskStatus polling every 100ms, so the test finishes right after the keeper reset lands (~6s instead of 35s). Signed-off-by: Jiwon Park <jpark92@outlook.kr>
Why are the changes needed?
Tables intermittently get stuck during self-optimizing, and the AMS log is flooded with:
The root cause is that the AMS can reset a task an optimizer is still working on, and then
reject that optimizer's valid response for it.
A task is reset (token cleared, status -> PLANNED) in two places:
OptimizerKeeper, when aSCHEDULEDtask's ack does not arrive withinoptimizer.task-ack-timeout— even though the optimizer is still alive (theSCHEDULED + ackTimeoutbranch ofbuildSuspendingPredicationdoes not check whether theowning token is still active).
resetStaleTasksForThread, when the same optimizer thread polls again while one of its tasksis still
ACKED.After the reset, the optimizer's in-flight ack/complete arrives and
TaskRuntime.validThreadsees
token == null, so it throws. This:PersistentBase"failed to commit transaction" plus the thrift layer), andSCHEDULED -> SUCCESStransition with
IllegalTaskStateException.In other words, a perfectly valid optimizer response is dropped with a noisy error.
The issue also reports the table becoming permanently stuck and uncancelable. That symptom could
not be reproduced from the excerpt logs and may need the full log to confirm, so this PR uses
"Relates to" rather than "Close".
Note: #4239 lowers the client-side log level for the same exception. This PR addresses the
server-side root cause instead, and additionally covers the completion path that #4239 does not.
Brief change log
TaskRuntimenow recognizes a stale response by(token, threadId, status)instead of throwingunconditionally in
validThread:optimizer skips the obsolete round, without the misleading "failed to commit transaction" error.
The exception message is preserved so existing clients still recognize it.
the task will be re-executed in its current round. This also removes the
IllegalTaskStateExceptionvariant and the equivalent race on canceled tasks.A WARN line is logged in both cases (with status and owner) so the situation stays observable.
How was this patch tested?
TestOptimizingQueuevia the realpollTaskpath: multi-task(stale ack is rejected) and single-task (stale completion is ignored).
TestDefaultOptimizingServicedriving the realOptimizerKeeper:a live optimizer (kept alive by heartbeats) leaves a
SCHEDULEDtask unacked past the acktimeout, the keeper resets it, and the late ack is rejected as expected. With the fix reverted,
this test reproduces the issue's exact log sequence and stack trace -- same messages and line
numbers, including the misleading "optimizer is expired" log for an optimizer that is in fact
still alive.
TestOptimizingQueueregression passes.Documentation