Siyao Meng created HDDS-16812:
---------------------------------
Summary: Evicted XceiverClientRatis is closed inline under the
XceiverClientManager cache lock, stalling a writer for 3 seconds
Key: HDDS-16812
URL: https://issues.apache.org/jira/browse/HDDS-16812
Project: Apache Ozone
Issue Type: Bug
Components: Ozone Client
Affects Versions: 2.3.0
Reporter: Siyao Meng
Assignee: Siyao Meng
h3. Problem
A thread calling {{XceiverClientManager.acquireClient}} can be blocked for
about 3 seconds because it ends up closing another, idle {{XceiverClientRatis}}
that was just evicted from the client cache. The close runs on the caller
thread and inside {{synchronized (clientCache)}}, so any other thread calling
{{acquireClient}} or {{releaseClient}} on the same manager has to wait as well.
HDDS-15849 fixed the same pattern for {{XceiverClientGrpc}} by making its close
use {{shutdownNow()}}. The {{XceiverClientRatis}} path is not covered, because
there the wait happens inside {{RaftClient.close()}}.
h3. How it was observed
HBase 2.6.7 region server writing its WAL (filesystem WAL provider, one WAL
file, hflush per sync) to Ozone master (2.3.0-SNAPSHOT at 24cf9aaa28e, Ratis
3.3.1), 3 datanodes, RATIS/THREE. Client settings:
{{ozone.client.incremental.chunk.list=true}},
{{ozone.client.stream.putblock.piggybacking=true}},
{{ozone.client.key.write.concurrency=-1}},
{{ozone.client.hbase.enhancements.allowed=true}}. Workload: YCSB load of 1M
rows with 16 threads.
In 2 of 15 load runs, all in flight WAL syncs stalled once for about 3 seconds.
HBase logged "Slow sync cost" of 3029 to 3043 ms on all five sync runner
threads at the same instant, and "append-pool-0 took 3029 ms appending an edit
to wal". The other run showed 3211 to 3217 ms. Datanode side Ratis timers
showed no stall at that time (leader write max about 100 to 240 ms). 8 ms
before the syncs completed, the region server logged:
{noformat}
WARN [Thread-80] grpc.GrpcUtil: Timed out gracefully shutting down connection:
ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=21,
target=172.18.0.3:9858}}.
{noformat}
Thread dumps taken every second show the WAL append thread in the following
state for three consecutive dumps, while starting a new block (shaded package
prefixes removed):
{noformat}
"regionserver/datanode:16020.append-pool-0" WAITING (parking)
at org.apache.ratis.util.PeerProxyMap.close(PeerProxyMap.java:185)
at
org.apache.ratis.client.impl.RaftClientRpcWithProxy.close(RaftClientRpcWithProxy.java:53)
at org.apache.ratis.grpc.client.GrpcClientRpc.close(GrpcClientRpc.java:234)
at org.apache.ratis.client.impl.RaftClientImpl.close(RaftClientImpl.java:472)
at
org.apache.hadoop.hdds.scm.XceiverClientRatis.closeRaftClient(XceiverClientRatis.java:233)
at
org.apache.hadoop.hdds.scm.XceiverClientRatis.close(XceiverClientRatis.java:227)
at
org.apache.hadoop.hdds.scm.XceiverClientSpi.cleanup(XceiverClientSpi.java:87)
at
org.apache.hadoop.hdds.scm.XceiverClientSpi.setEvicted(XceiverClientSpi.java:79)
at
org.apache.hadoop.hdds.scm.XceiverClientManager$1.onRemoval(XceiverClientManager.java:106)
- locked (a com.google.common.cache.LocalCache$LocalManualCache)
at
com.google.common.cache.LocalCache.processPendingNotifications(LocalCache.java:1845)
at
com.google.common.cache.LocalCache$Segment.runUnlockedCleanup(LocalCache.java:3493)
at
com.google.common.cache.LocalCache$Segment.postWriteCleanup(LocalCache.java:3469)
at
com.google.common.cache.LocalCache$Segment.lockedGetOrLoad(LocalCache.java:2174)
...
at
org.apache.hadoop.hdds.scm.XceiverClientManager.getClient(XceiverClientManager.java:190)
at
org.apache.hadoop.hdds.scm.XceiverClientManager.acquireClient(XceiverClientManager.java:157)
- locked (a com.google.common.cache.LocalCache$LocalManualCache)
at
org.apache.hadoop.hdds.scm.XceiverClientCreator.acquireClient(XceiverClientCreator.java:111)
at
org.apache.hadoop.hdds.scm.storage.BlockOutputStream.<init>(BlockOutputStream.java:204)
at
org.apache.hadoop.hdds.scm.storage.RatisBlockOutputStream.<init>(RatisBlockOutputStream.java:83)
at
org.apache.hadoop.ozone.client.io.BlockOutputStreamEntry.createOutputStream(BlockOutputStreamEntry.java:156)
at
org.apache.hadoop.ozone.client.io.BlockOutputStreamEntry.checkStream(BlockOutputStreamEntry.java:115)
at
org.apache.hadoop.ozone.client.io.BlockOutputStreamEntry.write(BlockOutputStreamEntry.java:182)
at
org.apache.hadoop.ozone.client.io.KeyOutputStream.writeToOutputStream(KeyOutputStream.java:299)
at
org.apache.hadoop.ozone.client.io.KeyOutputStream.handleWrite(KeyOutputStream.java:275)
"Thread-80" TIMED_WAITING (parking)
at java.util.concurrent.CountDownLatch.await
at
io.grpc.internal.ManagedChannelImpl.awaitTermination(ManagedChannelImpl.java:797)
at org.apache.ratis.grpc.GrpcUtil.shutdownManagedChannel(GrpcUtil.java:245)
at
org.apache.ratis.grpc.client.GrpcClientProtocolClient.close(GrpcClientProtocolClient.java:164)
at org.apache.ratis.util.PeerProxyMap.closeProxy(PeerProxyMap.java:201)
...
{noformat}
HBase has a single WAL append thread, so no second thread was waiting on the
cache lock in these dumps. The effect on other {{acquireClient}} and
{{releaseClient}} callers follows from the code.
h3. Mechanism
Checked on master at 8ca44914771 with Ratis 3.3.1. The code involved is the
same as at 24cf9aaa28e.
# {{XceiverClientManager}} keeps clients in a Guava cache built with
{{expireAfterAccess}} ({{scm.container.client.idle.threshold}}, default 10s),
{{maximumSize}} and a removal listener.
# Guava runs removal listeners on whichever thread next writes to the cache.
Here that is the writer inside {{acquireClient}}, which already holds
{{synchronized (clientCache)}}.
# The listener calls {{XceiverClientSpi.setEvicted()}}, and {{cleanup()}} calls
{{close()}} when the reference count is zero.
# {{XceiverClientRatis.close()}} calls {{RaftClient.close()}}.
{{PeerProxyMap.close()}} joins on closing every peer proxy, and
{{GrpcUtil.shutdownManagedChannel}} waits up to 3 s for graceful channel
termination, then up to 2 s more after {{shutdownNow()}}. The client and admin
channels of a peer are shut down one after the other, so the worst case is
about 10 s.
The same blocking close under the lock is reachable from {{releaseClient}},
through {{decrementReference()}} on an already evicted client and through
{{clientCache.invalidate(key)}}.
Expiry is measured from the last {{acquireClient}} call, not from the last use
or release. With the default 10s threshold, the client of a block that took
longer than 10 s to write is already expired when it is released, so the client
being closed can belong to a pipeline that was written to moments earlier.
The graceful shutdown completes only after the datanode completes the client's
request streams, which the Ratis server does once every outstanding request on
the stream has finished. So the stall needs a request from the evicted client
to be still pending on the datanode. Which request that was in these two cases
was not determined. Most evictions in the same runs did not stall.
h3. Proposed fix
Close evicted clients on a background thread owned by {{XceiverClientManager}},
outside the cache lock.
# {{XceiverClientSpi.setEvicted()}} and {{decrementReference()}} no longer call
{{close()}}. They return whether the client should now be closed, and
{{XceiverClientManager}} hands that client to a single daemon thread. This
covers all three paths above.
# Closes still run one at a time, as they effectively did under the cache lock,
so the number of threads does not grow with the number of evicted clients.
# The number of clients waiting to be closed is bounded by
{{scm.container.client.max.size}}. If the bound is reached, the client is
closed by the caller as it is today, which keeps backpressure in the extreme
case.
# {{XceiverClientManager.close()}} waits for pending closes.
A change in Ratis to let {{RaftClient.close()}} return without waiting for
graceful channel termination would shorten these closes further, but is not
needed for this fix.
--
This message was sent by Atlassian Jira
(v8.20.10#820010)
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
