[
https://issues.apache.org/jira/browse/SOLR-18480?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Lucas Kot-Zaniewski updated SOLR-18480:
---------------------------------------
Description:
h2. Summary
TLOG leader election stalls when the outgoing leader freezes rather than dies.
h2. Problem
When a TLOG replica wins an election,
{{ShardLeaderElectionContext.runLeaderProcess}} calls
{{zkController.stopReplicationFromLeader(coreName)}} inline on the election
thread
({{{}ShardLeaderElectionContext.java:254{}}}). The whole chain is synchronous
and unbounded:
{code:java}
ShardLeaderElectionContext:254 stopReplicationFromLeader
-> ZkController:1621 stopReplicationFromLeader (synchronized on
ReplicateFromLeader)
-> ReplicateFromLeader:189 stopReplication
-> ReplicationHandler:1496 shutdown()
startShutdownHook.preClose -> executorService.shutdown() //
no interrupt
startShutdownHook.postClose -> pollingIndexFetcher.destroy()
-> IndexFetcher.abortFetch() //
sets a flag only
-> IOUtils.closeQuietly(solrClient) //
no-op
ExecutorUtil.shutdownAndAwaitTermination(executorService) // <--
BLOCKS 60s (:1502)
{code}
If the old leader has _frozen_ rather than died, the follower's
{{indexFetcher}} poll thread is
parked inside an HTTP call to it, so the executor cannot terminate and the
election thread sits in
{{awaitTermination}} until the 60s deadline expires.
h2. Why nothing cuts it short
* {{IndexFetcher.abortFetch()}} ({{{}:1483{}}}) only sets {{volatile boolean
stop}} ({{{}:173{}}}), which is
polled in exactly one place – {{{}FileFetcher.fetchPackets{}}},
{{IndexFetcher.java:1669}} – and never
during the network call.
* {{IndexFetcher.destroy()}} ({{{}:1990{}}}) closes a client derived from
{{{}UpdateShardHandler.getRecoveryOnlyHttpClient(){}}}, so {{closeClient ==
false}} and
{{HttpJettySolrClient.close()}} skips {{{}httpClient.stop()/destroy(){}}}. No
socket is torn down.
* {{ExecutorUtil.shutdownAndAwaitTermination}} ({{{}ExecutorUtil.java:116{}}})
waits 60s, _then_ calls
{{{}shutdownNow(){}}}, then waits another 60s.
The unwind is ultimately driven by that {{shutdownNow()}} interrupt, not by any
socket timeout:
{{HttpJettySolrClient.request}} catches {{InterruptedException}} and calls
{{req.abort(abortCause)}}
in its {{finally}} ({{{}:531{}}}). The interrupt works – it just arrives 60s
too late. Since
{{soTimeout}} defaults to 120s ({{{}IndexFetcher.java:286{}}}), the executor
deadline always fires
first, which is why the stall is a flat ~60s rather than tracking how long the
peer stays frozen.
h2. Evidence
Reproduced on {{main}} with a 2-node cluster, one shard of two TLOG replicas:
the leader's
{{/replication?command=indexversion}} response is held open while its ZooKeeper
session is expired,
so the survivor runs an election with a fetch already parked in the network
phase.
Election took 62,553 ms (9 runs, 62.54--62.60s). On the surviving replica's
election thread:
{code:java}
7843 ms ZkController tlog_..._replica_t1 stopping background
replication from leader
67850 ms ShardLeaderElectionContext Replaying tlog before become new leader
{code}
60,007 ms. The same code path completes in 111 ms during normal collection
creation.
was:
h2. Summary
TLOG leader election stalls for a flat ~60s when the outgoing leader freezes
rather than dies.
h2. Problem
When a TLOG replica wins an election,
{{ShardLeaderElectionContext.runLeaderProcess}} calls
{{zkController.stopReplicationFromLeader(coreName)}} inline on the election
thread
({{ShardLeaderElectionContext.java:254}}). The whole chain is synchronous and
unbounded:
{code}
ShardLeaderElectionContext:254 stopReplicationFromLeader
-> ZkController:1621 stopReplicationFromLeader (synchronized on
ReplicateFromLeader)
-> ReplicateFromLeader:189 stopReplication
-> ReplicationHandler:1496 shutdown()
startShutdownHook.preClose -> executorService.shutdown() //
no interrupt
startShutdownHook.postClose -> pollingIndexFetcher.destroy()
-> IndexFetcher.abortFetch() //
sets a flag only
-> IOUtils.closeQuietly(solrClient) //
no-op
ExecutorUtil.shutdownAndAwaitTermination(executorService) // <--
BLOCKS 60s (:1502)
{code}
If the old leader has _frozen_ rather than died, the follower's
{{indexFetcher}} poll thread is
parked inside an HTTP call to it, so the executor cannot terminate and the
election thread sits in
{{awaitTermination}} until the 60s deadline expires.
h2. Why nothing cuts it short
* {{IndexFetcher.abortFetch()}} ({{:1483}}) only sets {{volatile boolean stop}}
({{:173}}), which is
polled in exactly one place -- {{FileFetcher.fetchPackets}},
{{IndexFetcher.java:1669}} -- and never
during the network call.
* {{IndexFetcher.destroy()}} ({{:1990}}) closes a client derived from
{{UpdateShardHandler.getRecoveryOnlyHttpClient()}}, so {{closeClient == false}}
and
{{HttpJettySolrClient.close()}} skips {{httpClient.stop()/destroy()}}. No
socket is torn down.
* {{ExecutorUtil.shutdownAndAwaitTermination}} ({{ExecutorUtil.java:116}})
waits 60s, _then_ calls
{{shutdownNow()}}, then waits another 60s.
The unwind is ultimately driven by that {{shutdownNow()}} interrupt, not by any
socket timeout:
{{HttpJettySolrClient.request}} catches {{InterruptedException}} and calls
{{req.abort(abortCause)}}
in its {{finally}} ({{:531}}). The interrupt works -- it just arrives 60s too
late. Since
{{soTimeout}} defaults to 120s ({{IndexFetcher.java:286}}), the executor
deadline always fires
first, which is why the stall is a flat ~60s rather than tracking how long the
peer stays frozen.
h2. Evidence
Reproduced on {{main}} with a 2-node cluster, one shard of two TLOG replicas:
the leader's
{{/replication?command=indexversion}} response is held open while its ZooKeeper
session is expired,
so the survivor runs an election with a fetch already parked in the network
phase.
Election took 62,553 ms (9 runs, 62.54--62.60s). On the surviving replica's
election thread:
{code}
7843 ms ZkController tlog_..._replica_t1 stopping background
replication from leader
67850 ms ShardLeaderElectionContext Replaying tlog before become new leader
{code}
60,007 ms. The same code path completes in 111 ms during normal collection
creation.
> TLOG leader election stalls on a frozen old leader
> --------------------------------------------------
>
> Key: SOLR-18480
> URL: https://issues.apache.org/jira/browse/SOLR-18480
> Project: Solr
> Issue Type: Bug
> Reporter: Lucas Kot-Zaniewski
> Assignee: Lucas Kot-Zaniewski
> Priority: Major
>
> h2. Summary
> TLOG leader election stalls when the outgoing leader freezes rather than dies.
> h2. Problem
> When a TLOG replica wins an election,
> {{ShardLeaderElectionContext.runLeaderProcess}} calls
> {{zkController.stopReplicationFromLeader(coreName)}} inline on the election
> thread
> ({{{}ShardLeaderElectionContext.java:254{}}}). The whole chain is synchronous
> and unbounded:
> {code:java}
> ShardLeaderElectionContext:254 stopReplicationFromLeader
> -> ZkController:1621 stopReplicationFromLeader (synchronized on
> ReplicateFromLeader)
> -> ReplicateFromLeader:189 stopReplication
> -> ReplicationHandler:1496 shutdown()
> startShutdownHook.preClose -> executorService.shutdown()
> // no interrupt
> startShutdownHook.postClose -> pollingIndexFetcher.destroy()
> -> IndexFetcher.abortFetch()
> // sets a flag only
> -> IOUtils.closeQuietly(solrClient)
> // no-op
> ExecutorUtil.shutdownAndAwaitTermination(executorService) // <--
> BLOCKS 60s (:1502)
> {code}
> If the old leader has _frozen_ rather than died, the follower's
> {{indexFetcher}} poll thread is
> parked inside an HTTP call to it, so the executor cannot terminate and the
> election thread sits in
> {{awaitTermination}} until the 60s deadline expires.
> h2. Why nothing cuts it short
> * {{IndexFetcher.abortFetch()}} ({{{}:1483{}}}) only sets {{volatile boolean
> stop}} ({{{}:173{}}}), which is
> polled in exactly one place – {{{}FileFetcher.fetchPackets{}}},
> {{IndexFetcher.java:1669}} – and never
> during the network call.
> * {{IndexFetcher.destroy()}} ({{{}:1990{}}}) closes a client derived from
> {{{}UpdateShardHandler.getRecoveryOnlyHttpClient(){}}}, so {{closeClient ==
> false}} and
> {{HttpJettySolrClient.close()}} skips {{{}httpClient.stop()/destroy(){}}}. No
> socket is torn down.
> * {{ExecutorUtil.shutdownAndAwaitTermination}}
> ({{{}ExecutorUtil.java:116{}}}) waits 60s, _then_ calls
> {{{}shutdownNow(){}}}, then waits another 60s.
> The unwind is ultimately driven by that {{shutdownNow()}} interrupt, not by
> any socket timeout:
> {{HttpJettySolrClient.request}} catches {{InterruptedException}} and calls
> {{req.abort(abortCause)}}
> in its {{finally}} ({{{}:531{}}}). The interrupt works – it just arrives 60s
> too late. Since
> {{soTimeout}} defaults to 120s ({{{}IndexFetcher.java:286{}}}), the executor
> deadline always fires
> first, which is why the stall is a flat ~60s rather than tracking how long
> the peer stays frozen.
> h2. Evidence
> Reproduced on {{main}} with a 2-node cluster, one shard of two TLOG replicas:
> the leader's
> {{/replication?command=indexversion}} response is held open while its
> ZooKeeper session is expired,
> so the survivor runs an election with a fetch already parked in the network
> phase.
> Election took 62,553 ms (9 runs, 62.54--62.60s). On the surviving replica's
> election thread:
> {code:java}
> 7843 ms ZkController tlog_..._replica_t1 stopping background
> replication from leader
> 67850 ms ShardLeaderElectionContext Replaying tlog before become new leader
> {code}
> 60,007 ms. The same code path completes in 111 ms during normal collection
> creation.
--
This message was sent by Atlassian Jira
(v8.20.10#820010)
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
