Siyao Meng created HDDS-17269:
---------------------------------
Summary: Datanode heartbeat queued behind a slow one runs after
SCM asks to reregister and drops pending container actions
Key: HDDS-17269
URL: https://issues.apache.org/jira/browse/HDDS-17269
Project: Apache Ozone
Issue Type: Bug
Reporter: Siyao Meng
Attachments:
MC-6-wait-for-running-endpoint-task-instead-of-queuing.patch,
TestBugCR1StaleEndpointBacklog.java, TestBugMC11HeartbeatAfterReregister.java,
TestBugMC6EndpointTaskBacklog.java
h3. Mechanism
{{RunningDatanodeState.execute}} builds one task per endpoint on every
heartbeat cycle, from the endpoint's state at that moment, and submits it to
the endpoint's single thread executor (created in {{EndpointStateMachine}},
unbounded queue). It waits for the task for at most one heartbeat interval,
does not cancel it when that wait times out, and does not check whether the
endpoint's previous task is still running. A queued task runs later for the
endpoint state and the endpoint object it was built for.
{{VersionEndpointTask}} and {{RegisterEndpointTask}} check the endpoint state
under the endpoint lock and do nothing if it has moved on.
{{HeartbeatEndpointTask.call}} has no such check: it drains the incremental
reports and container actions queued for that SCM address and sends them (close
pipeline actions are only read: {{PipelineActionMap.getActions}} keeps them
queued until the pipeline is gone). If the call fails with an {{IOException}},
only incremental container reports and command status reports are put back.
A cycle starts while the previous task is still running in two ways. The
heartbeat RPC takes longer than {{hdds.heartbeat.interval}} (with the defaults,
a call to an SCM that accepts the connection but does not answer takes about
95s by calculation: 16 attempts of the 5s {{ozone.scm.heartbeat.rpc-timeout}}
and 15 retry sleeps of 1s). Or {{DatanodeStateMachine.triggerHeartbeat}}
(immediate ICR, close container action, pipeline close) interrupts the state
machine thread while a heartbeat is in flight, and the next cycle starts at
once.
This shows up in three ways:
# *Backlog and burst.* While an SCM is reachable but answers more slowly than
the heartbeat interval, the endpoint queue grows by one task per heartbeat
cycle (every interval, and on every immediate heartbeat trigger) for as long as
that lasts, and the queue is replayed back to back as soon as the SCM answers
again.
# *Heartbeat after a reregister command.* If the heartbeat in flight gets a
reregister command (the SCM restarted or failed over and lost the
registration), {{HeartbeatEndpointTask.processReregisterCommand}} moves the
endpoint to GETVERSION. The queued heartbeat task then runs in GETVERSION,
drains what was raised in the meantime and sends it to an SCM that does not
consider the datanode registered. {{SCMDatanodeHeartbeatDispatcher}} answers
with another reregister command and processes none of the reports or actions.
# *Old endpoint after a DNS refresh.* This path was added by HDDS-15533 and is
not released yet. With {{ozone.client.failover.resolve-needed=true}} (default
false), a heartbeat that fails with a connection class error after
{{hdds.heartbeat.address.refresh.missed-count-threshold}} misses calls
{{SCMConnectionManager.refreshSCMServer}}. That replaces the endpoint under the
same {{HostAndPort}} key and calls {{EndpointStateMachine.close}} on the old
one, which uses {{ExecutorService.shutdown()}}. Tasks already queued on the old
endpoint still run: they heartbeat to the old address and drain the queues that
the rebuilt endpoint shares under the same {{HostAndPort}}.
h3. Trigger
* Backlog: an SCM that stays reachable but answers heartbeats more slowly than
the heartbeat interval, for example with saturated handlers or a long GC pause.
* Heartbeat after a reregister command: an SCM restart or failover while a
heartbeat to that SCM is in flight and the next cycle starts before it returns.
Either the first heartbeat after the restart takes longer than the interval, or
an immediate heartbeat trigger lands while its RPC is in flight.
* Old endpoint (HDDS-15533, not yet released): DNS refresh enabled, the SCM
moves to a new IP, and the old IP still accepts connections but does not answer
(when the old IP refuses connections the IPC client re-resolves the host by
itself and the refresh path is not reached). Heartbeats queued during the
misses before the refresh form the old endpoint's backlog.
h3. Impact
* The SCM receives the queued heartbeats as a burst after it recovers. Each one
is built when it runs, so it carries current data, and SCM's heartbeat handling
is idempotent, so on its own this is extra load on SCM and one small queued
task per interval in the datanode heap.
* After a reregister command, the reports and actions drained by the queued
heartbeat are gone from the datanode. Shown for a close container action and an
incremental container report. The replica state in the lost ICR is also in the
full container report sent at re-registration. A lost close container action is
added again by {{HddsDispatcher.sendCloseContainerActionIfNeeded}} on the next
write to that container, so it only stays lost if no write reaches the
container afterwards; then the container stays OPEN in SCM until its pipeline
is closed. That last step is argued from the code, not run here.
* After a DNS refresh, a container action drained by the old endpoint's backlog
is lost the same way when the call to the old address fails (shown).
Incremental reports drained there are put back, but only after each such call
fails (about 95s each with the defaults). The old endpoint also logs "Unable to
communicate to SCM server at <host>:<port>/<new IP>" because it shares the
updated {{HostAndPort}} (code reading).
h3. Reproduction
Three self contained classes for {{hadoop-hdds/container-service}} (target path
and Maven command in each class comment). Each one runs heartbeat cycles
through {{StateContext.execute}}, the call the datanode state machine thread
makes every interval, with the real {{RunningDatanodeState}},
{{EndpointStateMachine}} and {{HeartbeatEndpointTask}}. Only the SCM RPC proxy
is a stub; it holds the first heartbeat until the test releases it, which
stands for a slow call. The third class also runs the real
{{SCMConnectionManager.refreshSCMServer}} and {{EndpointStateMachine.close}},
with the DNS answer stubbed ({{HostAndPort.resolveLatest}}). They pass on
unmodified source when the bug is present.
* [^TestBugMC6EndpointTaskBacklog.java]: 10 cycles while the SCM holds the
first heartbeat. Output without the fix:
{noformat}Heartbeat cycles while SCM was slow: 10, heartbeats SCM received
right after it answered again: 10{noformat}
* [^TestBugMC11HeartbeatAfterReregister.java]: the SCM answers every heartbeat
with a reregister command; a close container action and an ICR are raised while
the first heartbeat is in flight and a second cycle starts. Output without the
fix:
{noformat}Heartbeats sent: [endpoint HEARTBEAT, container actions 0, ICRs 0,
endpoint GETVERSION, container actions 1, ICRs 1]; endpoint now GETVERSION;
container actions still queued for SCM: 0, ICRs: 0{noformat}
* [^TestBugCR1StaleEndpointBacklog.java]: refresh threshold 1, the old address
holds the first heartbeat and then times out, a close container action is
raised right after the rebuild. Output without the fix:
{noformat}Endpoint rebuilt: true, now dialing /10.0.0.7:9861; container actions
in each heartbeat to the old address: [0, 1, 0]; actions still queued for the
rebuilt endpoint: 0{noformat}
The full chain on a real cluster (SCM restart under load, then a container that
stays OPEN) was not run.
h3. Patch
[^MC-6-wait-for-running-endpoint-task-instead-of-queuing.patch], against
b10a7d427bdf83807a7e48a1be507d3b02d5a503. It also applies to master at
e0de543cbe9.
{{RunningDatanodeState}} remembers the last task it submitted to each endpoint.
If that task is still running when the next cycle starts, the cycle waits for
it (with the same bounded wait as before) instead of building and queuing
another one. If it finishes during that cycle, the next cycle starts right
away, so a heartbeat triggered while it was running is sent as soon as it
returns, as before (this also happens when nothing was triggered, which costs
at most one early heartbeat after a slow call). Every task is therefore built
after the previous one finished, from the current endpoint state and the
current endpoint list, which removes all three symptoms with one change: there
is no backlog, no heartbeat built before a reregister command runs after it,
and the replaced endpoint gets no new task after the refresh. The task is now
submitted to the endpoint executor from the state machine thread; an endpoint
closed between listing and submitting is skipped. Nothing changes for an SCM
that answers within the interval.
HDDS-17267 puts container actions back when a heartbeat fails or is answered
with a reregister command, which also covers the first heartbeat sent normally
after an SCM restart; this patch stops queued heartbeats from draining the
queues at all, so the two changes are independent, touch different files and
apply together.
Alternatives considered: a state check in {{HeartbeatEndpointTask.call}} fixes
only the second symptom, and {{shutdownNow()}} in
{{EndpointStateMachine.close}} only the third (it would also interrupt an in
flight call on SCM removal). Neither bounds the queue.
Covered by three cases in the existing {{TestRunningDatanodeState}}:
{{testEndpointTaskIsNotQueuedBehindRunningOne}},
{{testTaskAfterReregisterIsBuiltForNewEndpointState}} and
{{testReplacedEndpointRunsNoQueuedTask}}, plus {{testClosedEndpointIsSkipped}}
for the closed endpoint path (it passes without the change too, where the same
race only logged an error). Without the change they fail ("Wanted 1 time ...
But was 4 times" for {{sendHeartbeat}}, and the close container action missing
from the queue in the other two). With it they pass, together with the existing
tests of {{TestRunningDatanodeState}}, {{TestDatanodeStateMachine}},
{{TestHeartbeatEndpointTask}}, {{TestHeartbeatEndpointTaskDnsRefresh}},
{{TestSCMConnectionManager}}, {{TestStateContext}}, the command handler tests,
{{TestEndPoint}} and the mini cluster suite
{{TestDatanodeSCMNodesReconfiguration}} (SCM nodes added and removed at
runtime). Checkstyle is clean. With the change the three attached reproductions
fail at their bug assertions: the SCM gets 1 heartbeat instead of 10, and in
the other two only the first heartbeat is sent and the close container action
is still queued.
Found by TLA+ model checking and code review of the datanode registration and
heartbeat paths under HDDS-15926, on commit
b10a7d427bdf83807a7e48a1be507d3b02d5a503. Checked against HDDS issues and
apache/ozone pull requests for duplicates before filing. Related but not
duplicates: HDDS-4386 (introduced the per endpoint executor to stop thread
growth with a slow SCM), HDDS-13126 (datanode down after an endpoint task
timeout), HDDS-6634 (reregister goes to GETVERSION), HDDS-15533 (the DNS
refresh on heartbeat failure) and HDDS-16723 (oversized heartbeat from queued
ICRs on re-registration). The attached patch is a proposal for review.
Generated with Specula (Claude Opus 5.5).
--
This message was sent by Atlassian Jira
(v8.20.10#820010)
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
