[
https://issues.apache.org/jira/browse/HDDS-15255?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Andrey Yarovoy updated HDDS-15255:
----------------------------------
Summary: Ozone client shutdown waits 3 s for each Ratis channel that
doesn't close gracefully, one channel at a time (was: Timeouts on
ManagedChannels shutdown at the end ozone freon dfsg execution)
> Ozone client shutdown waits 3 s for each Ratis channel that doesn't close
> gracefully, one channel at a time
> -----------------------------------------------------------------------------------------------------------
>
> Key: HDDS-15255
> URL: https://issues.apache.org/jira/browse/HDDS-15255
> Project: Apache Ozone
> Issue Type: Bug
> Reporter: Andrey Yarovoy
> Assignee: Andrey Yarovoy
> Priority: Major
> Labels: pull-request-available
>
> *Problem*
> When a process using the Ozone client closes its FileSystem (explicitly or
> through Hadoop's `ClientFinalizer`
> shutdown hook), `XceiverClientManager.close()` closes every cached
> `XceiverClientRatis` **one at a time**. Each
> close ends in Ratis `GrpcUtil.shutdownManagedChannel()`, which waits up to
> **3 s** for the channel to terminate
> gracefully, then up to 2 s more after `shutdownNow()`. Both timeouts are
> hard-coded. Every channel that doesn't
> drain within the grace period adds 3 s to the exit, and they add up.
> Originally seen at the end of `ozone freon dfsg`. It also happens in ordinary
> Hadoop clients. Below, the TestDFSIO
> MapReduce client spends up to a minute exiting after its job has completed.
> *Evidence*
> Cluster: 12 datanodes, Ozone 2.2.0), Kerberos, `hdds.grpc.tls.enabled=true`,
> 72–74 RATIS/THREE
> pipelines. Client: `hadoop jar ... TestDFSIO -write|-read -nrFiles N -size
> 128MB` against `ofs://`.
> After `Job ... completed successfully`, the client logs one line every 3 s,
> then exits:
> ```
> 26/10/20 17:20:02 INFO mapreduce.Job: Job job_1792540199743_0014 completed
> successfully
> 26/10/20 17:20:02 INFO fs.TestDFSIO: ----- TestDFSIO ----- : write
> ...
> 26/10/20 17:20:05 WARN grpc.GrpcUtil: Timed out gracefully shutting down
> connection:
> ManagedChannelOrphanWrapper\{delegate=ManagedChannelImpl{logId=19,
> target=10.15.25.26:9858}}.
> 26/10/20 17:20:08 WARN grpc.GrpcUtil: Timed out gracefully shutting down
> connection:
> ManagedChannelOrphanWrapper\{delegate=ManagedChannelImpl{logId=137,
> target=10.15.25.39:9858}}.
> 26/10/20 17:20:11 WARN grpc.GrpcUtil: Timed out gracefully shutting down
> connection: ManagedChannelOrphanWrapper\{delegate=ManagedChannelImpl{logId=5,
> target=10.15.25.38:9858}}.
> ...
> 26/10/20 17:20:32 WARN util.ShutdownHookManager: ShutdownHook
> 'ClientFinalizer' timeout, java.util.concurrent.TimeoutException
> ...
> 26/10/20 17:20:56 WARN grpc.GrpcUtil: Timed out gracefully shutting down
> connection: ManagedChannelOrphanWrapper\{delegate=ManagedChannelImpl{logId=8,
> target=10.15.25.13:9858}}.
> ```
> Exit time after the job completed, across 15 client runs:
> | channels that timed out | exit time after job completion |
> |---|---|
> | 0 | 0–1 s |
> | 1 | 3–4 s |
> | 4–5 | 12–16 s |
> | 8 | 24 s |
> | 12–13 | 36–39 s |
> | 18 | 54 s |
> That's exactly **3.0 s per timed-out channel**. The count varies from run to
> run (0–18) for the same workload. Above
> 10 channels the 30 s `ClientFinalizer` hook timeout
> (`hadoop.service.shutdown.timeout`) fires, and the closing
> carries on past it.
> At scale: in a 840-job TestDFSIO, **25% of client runs (207 of 839) spent
> more than 15 s outside the job,
> about 45 s each, 2.6 h of the matrix's 13.1 h of wall time**. Applications
> with short-lived clients (CLI commands,
> Hive or Spark drivers, schedulers that launch many small processes) pay this
> on every exit. Map-task containers
> also close their FileSystem on exit and may hit it too. That would delay
> container release between task waves
> (not verified).
> *Code path (master)*
> ```
> XceiverClientManager.close()
> clientCache.invalidateAll(); clientCache.cleanUp(); // "closing is done
> through RemovalListener"
> removalListener.onRemoval() // one entry at a time, inside synchronized
> (clientCache)
> XceiverClientSpi.setEvicted() -> cleanup()
> XceiverClientRatis.close() -> RaftClient.close()
> GrpcClientProtocolClient.close() // Ratis: half-closes the streams, then
> GrpcUtil.shutdownManagedChannel(channel) // awaitTermination(3 s),
> shutdownNow(), awaitTermination(2 s)
> ```
> `awaitTermination` returns only when the channel's in-flight calls have
> finished, so a channel times out when the
> datanode hasn't completed the client's stream within 3 s of the half-close.
> Why some don't is not known yet.
> HDDS-15670 attributed it to server-side latency under a disconnect storm and
> couldn't reproduce it on a 3-datanode
> compose cluster; it reproduces readily on this 12-datanode cluster with TLS.
> *Proposed fix*
> 1. **Close in parallel on shutdown.** In `XceiverClientManager.close()`,
> collect the cached clients and close them
> concurrently on a bounded pool, so that exit costs about one grace period
> (3–5 s) instead of the sum of them. That
> also removes the per-close work from inside `synchronized (clientCache)`.
> 2. **Ratis follow-up (optional):** make the graceful-shutdown timeout
> configurable, or let `RaftClient.close()` skip
> the graceful wait, as HDDS-16812 also notes. A client that is exiting gains
> nothing from waiting for a drain.
> 3. **Investigate the datanode side:** why some client streams aren't
> completed within 3 s of the client's half-close.
> Interaction with HDDS-16812 (patch available): it moves eviction closes to a
> single background thread and makes
> `XceiverClientManager.close()` wait for pending closes. That fixes the writer
> stall, but on shutdown the closes
> would still be serial. Fix 1 should apply to the pending queue as well.
> *How to reproduce*
> On a multi-datanode cluster with RATIS/THREE pipelines, run a client that
> writes to many pipelines and then exits,
> and time the gap between its last operation and process exit:
> ```
> time hadoop jar hadoop-mapreduce-client-jobclient-*-tests.jar TestDFSIO -D
> fs.defaultFS=ofs://<om-service>/ \
> -D test.build.data=/<vol>/<ratis3-bucket>/TestDFSIO -libjars
> <ozone-filesystem-hadoop3.jar> \
> -write -nrFiles 1000 -size 128MB
> # or: ozone freon dfsg -n 10000 -t 160 -p
> ofs://<om-service>/<vol>/<bucket>/dfsg
> ```
> Then count the `Timed out gracefully shutting down connection` lines after
> the last operation; each costs 3 s.
> *Links*
> - relates to HDDS-16812 (same 3 s Ratis close, on cache eviction under the
> cache lock)
> - relates to HDDS-15670 (same warning, resolved Cannot Reproduce as log noise)
> - relates to HDDS-14474 (Freon dfsg FileSystem leak; fixed, not this)
--
This message was sent by Atlassian Jira
(v10.3.26#10030026)
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
