[
https://issues.apache.org/jira/browse/HDDS-15255?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Andrey Yarovoy updated HDDS-15255:
----------------------------------
Description:
*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)
was:
At the end of "ozone freon dfsg" execution the shutdown of ManagedChannels can
take up to 20+ seconds.
For example:
{noformat}
26/05/06 18:12:39 INFO netty.NettyConfigKeys$DataStream: setTlsConf
GrpcTlsConfig5666-
99.31%
|████████████████████████████████████████████████████████████████████████████████████████████████████
| 9931/10000 Time: 0:04:26|
26/05/06 18:12:39 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection: ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=6033,
target=10.15.25.14:9858}}.
26/05/06 18:12:39 INFO netty.NettyConfigKeys$DataStream: setTlsConf
GrpcTlsConfig5667-
26/05/06 18:12:39 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=13881,
target=10.15.25.33:9858}}.
26/05/06 18:12:39 INFO netty.NettyConfigKeys$DataStream: setTlsConf
GrpcTlsConfig5668-
26/05/06 18:12:39 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection: ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=797,
target=10.15.25.20:9858}}.
26/05/06 18:12:39 INFO netty.NettyConfigKeys$DataStream: setTlsConf
GrpcTlsConfig5669-
26/05/06 18:12:41 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection: ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=6173,
target=10.15.25.14:9858}}.
26/05/06 18:12:41 INFO netty.NettyConfigKeys$DataStream: setTlsConf
GrpcTlsConfig5670-
26/05/06 18:12:41 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=12573,
target=10.15.25.38:9858}}.
26/05/06 18:12:42 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=19653,
target=10.15.25.14:9858}}.
26/05/06 18:12:42 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=20245,
target=10.15.25.38:9858}}.
26/05/06 18:12:42 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection: ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=2821,
target=10.15.25.18:9858}}.
26/05/06 18:12:42 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=19349,
target=10.15.25.18:9858}}.
26/05/06 18:12:42 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=14629,
target=10.15.25.18:9858}}.
26/05/06 18:12:42 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=15549,
target=10.15.25.18:9858}}.
26/05/06 18:12:42 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=17953,
target=10.15.25.24:9858}}.
26/05/06 18:12:42 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection: ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=1661,
target=10.15.25.14:9858}}.
26/05/06 18:12:42 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection: ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=6857,
target=10.15.25.20:9858}}.
26/05/06 18:12:42 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=12617,
target=10.15.25.38:9858}}.
26/05/06 18:12:42 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=14525,
target=10.15.25.33:9858}}.
26/05/06 18:12:42 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=22353,
target=10.15.25.35:9858}}.
26/05/06 18:12:42 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=17117,
target=10.15.25.20:9858}}.
26/05/06 18:12:42 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=20669,
target=10.15.25.18:9858}}.
26/05/06 18:12:42 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=19581,
target=10.15.25.18:9858}}.
26/05/06 18:12:42 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=19541,
target=10.15.25.34:9858}}.
26/05/06 18:12:42 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=11745,
target=10.15.25.14:9858}}.
26/05/06 18:12:42 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=20057,
target=10.15.25.20:9858}}.
26/05/06 18:12:42 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=14173,
target=10.15.25.25:9858}}.
26/05/06 18:12:42 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=14069,
target=10.15.25.20:9858}}.
26/05/06 18:12:42 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=13225,
target=10.15.25.14:9858}}.
26/05/06 18:12:42 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=17041,
target=10.15.25.18:9858}}.
26/05/06 18:12:42 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=14749,
target=10.15.25.39:9858}}.
26/05/06 18:12:42 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=15701,
target=10.15.25.38:9858}}.
26/05/06 18:12:42 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection: ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=7524,
target=10.15.25.18:9858}}.
26/05/06 18:12:42 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=18093,
target=10.15.25.18:9858}}.
26/05/06 18:12:42 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection: ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=7169,
target=10.15.25.18:9858}}.
26/05/06 18:12:42 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=12665,
target=10.15.25.25:9858}}.
26/05/06 18:12:42 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=20529,
target=10.15.25.38:9858}}.
26/05/06 18:12:42 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=20857,
target=10.15.25.38:9858}}.
26/05/06 18:12:42 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection: ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=9897,
target=10.15.25.18:9858}}.
26/05/06 18:12:42 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=21749,
target=10.15.25.24:9858}}.
26/05/06 18:12:42 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection: ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=8217,
target=10.15.25.18:9858}}.
26/05/06 18:12:42 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=13749,
target=10.15.25.24:9858}}.
26/05/06 18:12:42 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=17577,
target=10.15.25.14:9858}}.
26/05/06 18:12:42 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=17873,
target=10.15.25.24:9858}}.
26/05/06 18:12:42 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection: ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=7109,
target=10.15.25.18:9858}}.
26/05/06 18:12:43 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=16321,
target=10.15.25.38:9858}}.
26/05/06 18:12:43 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=20481,
target=10.15.25.18:9858}}.
26/05/06 18:12:43 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=19189,
target=10.15.25.14:9858}}.
26/05/06 18:12:43 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=16753,
target=10.15.25.14:9858}}.
26/05/06 18:12:43 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection: ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=6137,
target=10.15.25.20:9858}}.
26/05/06 18:12:43 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=11845,
target=10.15.25.20:9858}}.
26/05/06 18:12:43 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=19181,
target=10.15.25.33:9858}}.
26/05/06 18:12:43 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=16461,
target=10.15.25.18:9858}}.
26/05/06 18:12:43 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=18985,
target=10.15.25.34:9858}}.
26/05/06 18:12:43 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection: ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=6329,
target=10.15.25.14:9858}}.
26/05/06 18:12:43 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection: ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=8181,
target=10.15.25.14:9858}}.
26/05/06 18:12:43 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=14193,
target=10.15.25.14:9858}}.
26/05/06 18:12:43 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=19093,
target=10.15.25.18:9858}}.
26/05/06 18:12:43 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection: ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=7721,
target=10.15.25.18:9858}}.
26/05/06 18:12:43 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=12557,
target=10.15.25.20:9858}}.
26/05/06 18:12:43 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection: ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=8049,
target=10.15.25.34:9858}}.
26/05/06 18:12:43 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=22153,
target=10.15.25.18:9858}}.
26/05/06 18:12:43 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection: ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=8225,
target=10.15.25.14:9858}}.
26/05/06 18:12:43 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=12489,
target=10.15.25.26:9858}}.
26/05/06 18:12:43 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=17321,
target=10.15.25.14:9858}}.
26/05/06 18:12:43 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=15465,
target=10.15.25.14:9858}}.
26/05/06 18:12:43 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=15401,
target=10.15.25.33:9858}}.
26/05/06 18:12:44 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=17185,
target=10.15.25.39:9858}}.
26/05/06 18:12:44 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection: ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=4129,
target=10.15.25.14:9858}}.
26/05/06 18:12:44 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=12133,
target=10.15.25.20:9858}}.
26/05/06 18:12:44 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=17693,
target=10.15.25.18:9858}}.
26/05/06 18:12:44 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=18965,
target=10.15.25.33:9858}}.
26/05/06 18:12:44 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection: ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=8469,
target=10.15.25.24:9858}}.
26/05/06 18:12:44 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection: ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=7009,
target=10.15.25.18:9858}}.
26/05/06 18:12:44 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=12173,
target=10.15.25.20:9858}}.
26/05/06 18:12:44 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection: ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=8833,
target=10.15.25.18:9858}}.
26/05/06 18:12:44 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=18029,
target=10.15.25.20:9858}}.
26/05/06 18:12:45 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=18337,
target=10.15.25.18:9858}}.
26/05/06 18:12:45 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=14225,
target=10.15.25.18:9858}}.
26/05/06 18:12:45 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=16713,
target=10.15.25.20:9858}}.
26/05/06 18:12:45 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=15381,
target=10.15.25.14:9858}}.
26/05/06 18:12:45 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=14957,
target=10.15.25.25:9858}}.
26/05/06 18:12:45 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=18189,
target=10.15.25.18:9858}}.
26/05/06 18:12:45 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=18269,
target=10.15.25.33:9858}}.
26/05/06 18:12:45 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=19961,
target=10.15.25.24:9858}}.
26/05/06 18:12:45 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=10245,
target=10.15.25.25:9858}}.
26/05/06 18:12:45 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection: ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=5237,
target=10.15.25.25:9858}}.
26/05/06 18:12:45 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=21221,
target=10.15.25.13:9858}}.
26/05/06 18:12:45 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection: ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=5549,
target=10.15.25.35:9858}}.
26/05/06 18:12:45 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=17725,
target=10.15.25.18:9858}}.
26/05/06 18:12:45 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection: ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=7493,
target=10.15.25.25:9858}}.
26/05/06 18:12:45 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=14269,
target=10.15.25.20:9858}}.
26/05/06 18:12:45 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=21161,
target=10.15.25.35:9858}}.
26/05/06 18:12:45 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=21965,
target=10.15.25.20:9858}}.
26/05/06 18:12:45 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=18397,
target=10.15.25.24:9858}}.
26/05/06 18:12:45 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=11973,
target=10.15.25.14:9858}}.
26/05/06 18:12:45 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=18289,
target=10.15.25.14:9858}}.
26/05/06 18:12:45 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=10589,
target=10.15.25.14:9858}}.
26/05/06 18:12:45 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection: ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=9441,
target=10.15.25.18:9858}}.
26/05/06 18:12:45 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=20745,
target=10.15.25.20:9858}}.
26/05/06 18:12:45 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=16325,
target=10.15.25.18:9858}}.
26/05/06 18:12:45 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=15725,
target=10.15.25.18:9858}}.
26/05/06 18:12:45 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection: ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=5733,
target=10.15.25.18:9858}}.
26/05/06 18:12:46 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection: ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=8645,
target=10.15.25.34:9858}}.
26/05/06 18:12:46 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection: ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=8573,
target=10.15.25.14:9858}}.
26/05/06 18:12:46 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=13345,
target=10.15.25.18:9858}}.
26/05/06 18:12:46 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=17857,
target=10.15.25.33:9858}}.
26/05/06 18:12:46 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=14777,
target=10.15.25.18:9858}}.
26/05/06 18:12:46 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=13269,
target=10.15.25.18:9858}}.
26/05/06 18:12:46 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=14397,
target=10.15.25.20:9858}}.
26/05/06 18:12:46 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=11077,
target=10.15.25.18:9858}}.
26/05/06 18:12:46 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=12793,
target=10.15.25.14:9858}}.
26/05/06 18:12:47 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=13577,
target=10.15.25.14:9858}}.
26/05/06 18:12:47 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=13257,
target=10.15.25.14:9858}}.
26/05/06 18:12:47 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=17469,
target=10.15.25.18:9858}}.
26/05/06 18:12:47 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=22157,
target=10.15.25.13:9858}}.
26/05/06 18:12:47 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=14513,
target=10.15.25.26:9858}}.
26/05/06 18:12:47 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=11689,
target=10.15.25.18:9858}}.
26/05/06 18:12:47 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=15945,
target=10.15.25.38:9858}}.
26/05/06 18:12:47 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection: ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=9817,
target=10.15.25.14:9858}}.
26/05/06 18:12:47 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection: ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=6661,
target=10.15.25.26:9858}}.
26/05/06 18:12:48 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=15225,
target=10.15.25.18:9858}}.
26/05/06 18:12:48 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=19565,
target=10.15.25.13:9858}}.
26/05/06 18:12:48 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=12585,
target=10.15.25.14:9858}}.
26/05/06 18:12:48 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=21173,
target=10.15.25.35:9858}}.
26/05/06 18:12:48 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=20037,
target=10.15.25.14:9858}}.
26/05/06 18:12:48 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=19889,
target=10.15.25.20:9858}}.
26/05/06 18:12:48 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=12641,
target=10.15.25.38:9858}}.
26/05/06 18:12:48 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=14117,
target=10.15.25.38:9858}}.
26/05/06 18:12:48 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=13265,
target=10.15.25.18:9858}}.
26/05/06 18:12:48 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=10737,
target=10.15.25.14:9858}}.
26/05/06 18:12:48 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection: ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=3857,
target=10.15.25.18:9858}}.
26/05/06 18:12:48 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=15169,
target=10.15.25.38:9858}}.
26/05/06 18:12:48 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection: ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=641,
target=10.15.25.18:9858}}.
26/05/06 18:12:48 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=15269,
target=10.15.25.25:9858}}.
26/05/06 18:12:48 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=18877,
target=10.15.25.20:9858}}.
26/05/06 18:12:48 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=15829,
target=10.15.25.14:9858}}.
26/05/06 18:12:48 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=15321,
target=10.15.25.20:9858}}.
26/05/06 18:12:49 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection: ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=8349,
target=10.15.25.24:9858}}.
26/05/06 18:12:49 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=14345,
target=10.15.25.20:9858}}.
26/05/06 18:12:49 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection: ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=9557,
target=10.15.25.18:9858}}.
26/05/06 18:12:49 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=13001,
target=10.15.25.38:9858}}.
26/05/06 18:12:49 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=18685,
target=10.15.25.33:9858}}.
26/05/06 18:12:49 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=21117,
target=10.15.25.20:9858}}.
26/05/06 18:12:50 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=15221,
target=10.15.25.33:9858}}.
26/05/06 18:12:50 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=20249,
target=10.15.25.18:9858}}.
26/05/06 18:12:50 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=16517,
target=10.15.25.18:9858}}.
26/05/06 18:12:50 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=15161,
target=10.15.25.33:9858}}.
26/05/06 18:12:50 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=19729,
target=10.15.25.18:9858}}.
26/05/06 18:12:50 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=11781,
target=10.15.25.14:9858}}.
26/05/06 18:12:50 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection: ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=6885,
target=10.15.25.14:9858}}.
26/05/06 18:12:51 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=13405,
target=10.15.25.20:9858}}.
26/05/06 18:12:51 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=17673,
target=10.15.25.14:9858}}.
26/05/06 18:12:51 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=21901,
target=10.15.25.24:9858}}.
26/05/06 18:12:51 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection: ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=3601,
target=10.15.25.14:9858}}.
26/05/06 18:12:51 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection: ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=1797,
target=10.15.25.14:9858}}.
26/05/06 18:12:51 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=19813,
target=10.15.25.18:9858}}.
26/05/06 18:12:51 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=18125,
target=10.15.25.14:9858}}.
26/05/06 18:12:51 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=13161,
target=10.15.25.35:9858}}.
26/05/06 18:12:51 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection: ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=6937,
target=10.15.25.18:9858}}.
26/05/06 18:12:51 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection: ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=6037,
target=10.15.25.35:9858}}.
26/05/06 18:12:52 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=10565,
target=10.15.25.14:9858}}.
26/05/06 18:12:52 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=12709,
target=10.15.25.38:9858}}.
26/05/06 18:12:52 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=13053,
target=10.15.25.14:9858}}.
26/05/06 18:12:52 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=18653,
target=10.15.25.33:9858}}.
26/05/06 18:12:53 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection: ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=6453,
target=10.15.25.26:9858}}.
26/05/06 18:12:53 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection: ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=5101,
target=10.15.25.18:9858}}.
26/05/06 18:12:54 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=17929,
target=10.15.25.14:9858}}.
26/05/06 18:12:54 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection: ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=4073,
target=10.15.25.18:9858}}.
26/05/06 18:12:54 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=18545,
target=10.15.25.14:9858}}.
26/05/06 18:12:54 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=18017,
target=10.15.25.34:9858}}.
26/05/06 18:12:54 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=22549,
target=10.15.25.13:9858}}.
26/05/06 18:12:55 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=22201,
target=10.15.25.18:9858}}.
26/05/06 18:12:55 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=13817,
target=10.15.25.20:9858}}.
26/05/06 18:12:56 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection: ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=7257,
target=10.15.25.20:9858}}.
26/05/06 18:12:57 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=16189,
target=10.15.25.14:9858}}.
26/05/06 18:13:00 WARN grpc.GrpcUtil: Timed out gracefully shutting down
connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=12633,
target=10.15.25.20:9858}}. {noformat}
> Timeouts on ManagedChannels shutdown at the end ozone freon dfsg execution
> ---------------------------------------------------------------------------
>
> 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]
