[
https://issues.apache.org/jira/browse/HDDS-16812?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Siyao Meng updated HDDS-16812:
------------------------------
Status: Patch Available (was: Open)
> 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
> Priority: Major
> Labels: pull-request-available
>
> 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]
