[
https://issues.apache.org/jira/browse/HDDS-17395?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Siyao Meng updated HDDS-17395:
------------------------------
Affects Version/s: 2.2.1
2.1.2
2.1.0
2.1.1
2.2.0
> Restarted BackgroundService can stop for good or run batches from its old
> executor after a forced shutdown
> ----------------------------------------------------------------------------------------------------------
>
> Key: HDDS-17395
> URL: https://issues.apache.org/jira/browse/HDDS-17395
> Project: Apache Ozone
> Issue Type: Bug
> Affects Versions: 2.1.0, 2.2.0, 2.1.1, 2.1.2, 2.2.1
> Reporter: Siyao Meng
> Priority: Major
> Attachments:
> MC-1-complete-dropped-tasks-and-stop-stale-background-service-loops.patch,
> TestBugMC1RestartAfterForcedShutdown.java,
> TestBugMC2StaleLoopOverlapsRestartedBatch.java,
> TestBugMC3SingleWorkerSelfDeadlock.java, TestBugMC4ShutdownDuringSubmit.java
>
>
> h3. Mechanism
> {{BackgroundService.PeriodicalTask.run}} waits for the previous batch with
> {{future.join()}} on the instance field {{future}}, then calls {{getTasks()}}
> and submits every task with {{CompletableFuture.runAsync(..., exec)}},
> folding each task's future into {{future}}. {{join()}} ignores interrupts.
> The submit reads the field {{exec}}, not the executor the run was scheduled
> on.
> {{shutdown()}} calls {{exec.shutdown()}}, waits 60 seconds in
> {{awaitTermination}}, and calls {{shutdownNow()}} when that wait runs out or
> the calling thread is interrupted. {{start()}} creates a new executor when
> the old one is shut down, but keeps {{future}}. Three things follow:
> * {{shutdownNow()}} removes the queued {{runAsync}} wrappers from the
> executor without running them, so their futures never complete, and neither
> does {{future}}. The first run of the restarted service waits on it forever.
> * A run that was waiting in {{join()}} during the restart is not stopped by
> {{shutdownNow()}}. When the slow task ends, it calls {{getTasks()}} and
> submits into {{exec}}, which is now the new executor, while the new
> executor's own run does the same.
> * Since HDDS-14645, {{shutdown()}} calls {{exec.shutdown()}} outside the
> monitor that the submit loop holds, so it can land between {{getTasks()}} and
> the submit. {{runAsync}} then throws {{RejectedExecutionException}}, which
> ends the run with no log line; the polled task is lost and the rest of the
> batch is abandoned.
> h3. Trigger
> {{BlockDeletingService.updateAndRestart}} and
> {{DirectoryDeletingService.updateAndRestart}} are the only callers that
> restart a service instance in place. They run when {{ozone admin reconfig}}
> changes {{hdds.datanode.block.deleting.service.interval}}
> ({{ozone.block.deleting.service.interval}} in 2.1 and 2.2),
> {{ozone.block.deleting.service.timeout}} or
> {{ozone.block.deleting.service.workers}} on a datanode, or
> {{ozone.directory.deleting.service.interval}} or
> {{ozone.thread.number.dir.deletion}} on an OM. The restart reaches
> {{shutdownNow()}} when the tasks still running or queued at that moment do
> not finish within 60 seconds. The interrupt path of {{shutdown()}} exists in
> the code, but nothing in Ozone interrupts the reconfiguration thread. After a
> plain {{exec.shutdown()}} the queued tasks still run, so a task is dropped
> only if it has not started when the 60 seconds run out.
> For {{BlockDeletingService}}, a batch has one task per container with pending
> deletes, up to {{hdds.datanode.block.deleting.limit.per.interval}} (20000
> blocks by default) in total, so on a datanode with a deletion backlog it
> often has more tasks than the 10 default workers. {{BlockDeletingTask}} does
> not check for interrupts. Tasks are dropped when such a batch is still
> running 60 seconds after the reconfiguration started, which is also when an
> operator is likely to retune deletion. This is argued from the code, not
> measured on a datanode. {{DirectoryDeletingService}} runs one worker since
> HDDS-16164, but its own {{shutdown()}} first shuts its deletion pool down,
> after which queued tasks return quickly, so it reaches {{shutdownNow()}} only
> when a task outlives that as well (argued from the code).
> h3. Impact
> All of the following were run on unmodified source against
> {{BackgroundService}} through its public methods, with a test subclass that
> restarts in the same order as {{updateAndRestart}}. No production service was
> run.
> * *Restarted service never runs again.* Pool size 1, first batch of two
> tasks, one running and one queued. After a restart whose {{shutdown()}} was
> interrupted, and after one whose 60 second wait really ran out, the restarted
> service called {{getTasks()}} zero times in 3 seconds at a 50 ms interval,
> with its only worker parked in {{CompletableFuture.join}} from
> {{PeriodicalTask.run}}. Nothing reassigns {{future}}, so this lasts until the
> process restarts, and by code reading every later {{shutdown()}} waits the
> full 60 seconds for the parked thread. For {{BlockDeletingService}} this
> means block deletion on that datanode stops while the service still counts as
> started. [^TestBugMC1RestartAfterForcedShutdown.java]
> * *Two batches at once.* Pool size 2, one task holding a worker through the
> restart and the next run waiting for it. After the task ended, both the old
> executor's run and the new executor's run fetched a batch, and the two
> batches ran at the same time on the new executor, against the class contract
> of one batch per interval. In {{BlockDeletingService}} the duplicate batch is
> absorbed ({{getTasks()}} only reads, and each task re-reads the container
> under its write lock), so this is a latent defect today (argued from the
> code). [^TestBugMC2StaleLoopOverlapsRestartedBatch.java]
> * *Single worker deadlock.* Pool size 1 and two restarts that both reach
> {{shutdownNow()}}: the run that survived the second restart submitted its
> task into the third executor, behind that executor's next run, which then
> waited in {{join()}} for a task that could only run on its own thread.
> {{getTasks()}} was not called again. The test orders the steps with latches,
> so it shows that the interleaving exists, not how often it occurs.
> [^TestBugMC3SingleWorkerSelfDeadlock.java]
> * *Batch dropped without a log line.* A {{shutdown()}} that landed after
> {{getTasks()}} had returned four tasks: one task was polled and neither ran
> nor was handed back, three were abandoned, and only the start and shutdown
> INFO lines were logged. The services restarted in place rebuild their batch
> from durable state on the next run, and the services whose {{getTasks()}}
> reserves state ({{KeyLifecycleService}}, {{DiskBalancerService}}) are only
> stopped together with their owner and then discarded, so no wrong result
> follows today (argued from the code). [^TestBugMC4ShutdownDuringSubmit.java]
> h3. Reproduction
> The four attached JUnit classes belong in
> {{hadoop-hdds/framework/src/test/java/org/apache/hadoop/util/}} (Maven
> command in each class comment) and pass on unmodified source while the bug is
> present. They only use {{start()}}, {{shutdown()}}, {{setInterval()}} and
> {{getExecutorService()}}. Except for one case of the first class, the forced
> shutdown is reached by interrupting the restarting thread, which takes the
> same {{shutdownNow()}} path as a 60 second wait that runs out, without
> waiting for it.
> h3. Patch
> [^MC-1-complete-dropped-tasks-and-stop-stale-background-service-loops.patch],
> against 9c3e5477ffb9f41da639051aaa5e9d7bd8b53fe4. It also applies to master
> at c521a16af75.
> All changes are in {{BackgroundService}}:
> * {{start()}} schedules a new {{PeriodicalTask}}, which keeps the executor it
> was scheduled on. A run whose executor has been shut down returns after
> {{join()}} without calling {{getTasks()}}, and the submit loop stops when its
> executor is shut down. So no run of an old executor reaches the new one.
> * Each submitted task registers its future in a set kept per executor and
> removes it when it starts. After {{shutdownNow()}}, {{shutdown()}} completes
> the futures still in the set, which belong to the tasks that were dropped and
> will never run. A task that had started is still waited for, so the restarted
> service does not run its first batch next to a task of the old executor that
> is still running.
> * {{shutdown()}} calls {{exec.shutdown()}} under the monitor, so it cannot
> land halfway through the submit loop. {{awaitTermination}} stays outside the
> monitor, as HDDS-15429 requires. {{exec.shutdown()}} does not wait for
> workers, and the submit loop already takes the executor's lock while holding
> the monitor, so this adds no new lock order. A batch fetched before the
> shutdown and not submitted is logged at INFO with its size.
> A service that is never restarted and whose shutdown finishes in time behaves
> as before. Resetting {{future}} in {{start()}} was not chosen: the new batch
> would then run next to tasks of the old executor that are still running, and
> a run of the old executor parked on a dropped task would stay parked.
> Covered by three new cases in the existing {{TestBackgroundService}}:
> {{testRestartAfterForcedShutdownSkipsDroppedTasks}},
> {{testLoopOfReplacedExecutorDoesNotFetchTasks}} and
> {{testShutdownWhileFetchingTasksDropsWholeBatch}}. Without the change they
> fail with a {{TimeoutException}} (the restarted run parked in {{join()}}),
> "Expecting AtomicInteger(2) to have value: 1" and "expected: 4 but was: 3".
> With it they pass, the existing suites of the {{BackgroundService}}
> subclasses in {{hadoop-hdds/container-service}} and
> {{hadoop-ozone/ozone-manager}} pass, checkstyle is clean, and the four
> attached classes no longer show the bug.
> Found by TLA+ model checking and code review of the BackgroundService restart
> and shutdown paths and the reconfiguration callback handling under
> HDDS-15926, on commit 9c3e5477ffb9f41da639051aaa5e9d7bd8b53fe4. Checked
> against HDDS issues and apache/ozone pull requests for duplicates before
> filing. Related but not duplicates: HDDS-15429 (monitor deadlock in
> {{updateAndRestart}}, whose fix stopped calling {{shutdown()}} under the
> monitor), HDDS-14645 (moved {{exec.shutdown()}} and {{awaitTermination}} out
> of the monitor), HDDS-14020 (open, the same lock shared by shutdown and the
> submit loop), HDDS-13773 (open, timeout and interrupt for background tasks),
> HDDS-14236 (fixed delay scheduling of {{PeriodicalTask}}, in progress, its PR
> closed), HDDS-16949 (an exception from {{getTasks()}} cancelled the periodic
> task) and HDDS-17296 (a replaced {{DirectoryDeletingService}} is restarted by
> its reconfiguration callback). The attached patch is a proposal for review.
> Generated with Specula (Claude Opus 5.5).
--
This message was sent by Atlassian Jira
(v10.3.26#10030026)
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
