Siyao Meng created HDDS-17280:
---------------------------------
Summary: Datanode command processor thread busy-spins and SCM
heartbeats come too often while Recon or another endpoint keeps failing
GETVERSION
Key: HDDS-17280
URL: https://issues.apache.org/jira/browse/HDDS-17280
Project: Apache Ozone
Issue Type: Bug
Reporter: Siyao Meng
Attachments:
CR-2-skip-heartbeat-wait-only-after-successful-getversion.patch,
TestBugCR2ReconDownHeartbeatInterval.java
h3. Mechanism
{{RunningDatanodeState.buildEndPointTask}} calls
{{DatanodeStateMachine.setNextHB(now)}} whenever it builds the task for an
endpoint in GETVERSION (added by HDDS-13981 so that REGISTER can follow
GETVERSION without waiting a full interval). The call happens before the task
runs and regardless of its result. The main loop in
{{DatanodeStateMachine.startStateMachineThread}} sleeps only until {{nextHB}},
so while an endpoint keeps failing GETVERSION it never sleeps: each cycle
starts as soon as the previous one ends, and the cycle lasts as long as the
failing {{getVersion}} call. All SCM heartbeats are sent at that pace. The
command processor thread started by
{{DatanodeStateMachine.initCommandHandlerThread}} sleeps only while {{nextHB}}
is in the future; with {{nextHB}} set to the cycle start it loops on
{{StateContext.getNextCommand}} without sleeping until it happens to see the
next cycle's {{nextHB}} before the GETVERSION task resets it, then sleeps one
interval and spins again in a later cycle.
h3. Trigger
An endpoint stays in GETVERSION because its server cannot be reached and the
call fails faster than {{hdds.heartbeat.interval}}. The common case is a
datanode that starts (or restarts) while Recon is down with the connection
refused: each Recon {{getVersion}} fails after
{{ozone.scm.heartbeat.rpc-retry-count}} x
{{ozone.scm.heartbeat.rpc-retry-interval}} (15 x 1s by default), so SCM gets a
heartbeat about every 15s instead of every 30s until Recon is back, or for good
if Recon is configured but not deployed. A datanode that registered with Recon
before the outage is not affected, because a failed heartbeat leaves the
endpoint in HEARTBEAT. The code has no Recon specific check, so an SCM endpoint
stuck in GETVERSION (for example one SCM of an HA group down while the datanode
starts) does the same (argued from the code, the end to end run used Recon). If
connection attempts time out instead of being refused, a call outlasts the
interval and the heartbeat interval is not shortened, but {{nextHB}} stays in
the past for the whole cycle, so the command processor thread would spin almost
continuously (argued from the code, not run).
h3. Impact
* The command processor thread of each affected datanode busy-spins, taking
{{StateContext.lock}} on every iteration. With a 10s interval and a 5s failing
call it used 4.0s of CPU over 15s of heartbeats (1 ms with the patch). With
default settings the same arithmetic gives about 14s of spinning in every 45s,
roughly a third of one core (argued, not run at production timings).
* SCM receives heartbeats from the affected datanodes about twice as often as
configured with default settings, faster with fewer retries.
{{hdds.heartbeat.interval}} is not honoured for that time.
* No correctness impact.
h3. Reproduction
[^TestBugCR2ReconDownHeartbeatInterval.java]
({{hadoop-hdds/container-service}}) runs a real {{DatanodeStateMachine}}
against an in process SCM ({{ScmTestMock}} behind a real RPC server) with
{{ozone.recon.address}} pointing at a closed port. Timings are scaled:
heartbeat interval 10s, Recon connection retries 5 x 1s. Over three SCM
heartbeats it asserts that they are more than 8s apart and that the command
processor thread used less than 1s of CPU. On unmodified code both fail: gaps
of [4946, 5006, 5028] ms (the length of the failing Recon call) and 4009 ms of
CPU. With the patch it passes (gaps of [9891, 10002, 10003] ms, 1 ms of CPU).
An earlier run at production defaults (30s interval, 15 x 1s retries) measured
gaps of about 15.0s with Recon down and 30.0s without Recon; it was not
repeated for the final test.
h3. Patch
[^CR-2-skip-heartbeat-wait-only-after-successful-getversion.patch], against
b10a7d427bdf83807a7e48a1be507d3b02d5a503. It also applies to master at
e0de543cbe9.
The GETVERSION task now calls {{setNextHB(now)}} after the
{{VersionEndpointTask}} has moved the endpoint to REGISTER, instead of when the
task is built. REGISTER still follows a successful GETVERSION at once, and a
failing GETVERSION is retried once per heartbeat interval as before HDDS-13981.
This also covers SCM endpoints, which a check for the Recon endpoint alone
would not.
Covered by {{testOnlySuccessfulGetVersionSkipsHeartbeatWait}} in the existing
{{TestRunningDatanodeState}}, for a Recon and an SCM endpoint: {{setNextHB}}
must not be called after a failed GETVERSION and must be called once after the
successful one. This is also what prevents the spin, which needs a real state
machine and seconds of timing and is therefore checked only by the
reproduction. Without the change the test fails for both endpoint types; with
it {{TestRunningDatanodeState}}, {{TestHeartbeatEndpointTask}} and
{{TestStateContext}} pass, checkstyle is clean.
Found by code review of the datanode registration and heartbeat paths, as part
of the TLA+ verification effort under HDDS-15926, on commit
b10a7d427bdf83807a7e48a1be507d3b02d5a503. Checked against HDDS issues and
apache/ozone pull requests for duplicates before filing. Related but not
duplicates: HDDS-13981 (added the {{setNextHB}} call) 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]
