[
https://issues.apache.org/jira/browse/GEODE-3718?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16871818#comment-16871818
]
Barry Oglesby commented on GEODE-3718:
--------------------------------------
This code change is after the issue has already happened. We can do this, but
it doesn't address the issue.
The issue is that when a member is stopped, the shutdown hook attempts to stop
the InternalResourceManager's scheduledExecutor. If that executor has any
pending tasks (including ones in the future), the shutdown hook blocks waiting
for them to fire.
If I run this test:
1. Start 3 servers defining a partitioned region with recovery-delay > 0
2. Load some data into the partitioned region
3. Kill one server using kill -9
4. The remaining servers schedule the recovery task
5. Stop the remaining servers normally (the JVMs do not stop)
The shutdown hook thread is waiting here for the InternalResourceManager's
scheduledExecutor to terminate:
{noformat}
"Distributed system shutdown hook" #12 prio=5 os_prio=31 tid=0x00007ff0f8c33000
nid=0x12307 waiting on condition [0x000070000bc11000]
java.lang.Thread.State: TIMED_WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x0000000766c00038> (a
java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
at
java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
at
java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2078)
at
java.util.concurrent.ThreadPoolExecutor.awaitTermination(ThreadPoolExecutor.java:1465)
at
org.apache.geode.internal.cache.control.InternalResourceManager.stopExecutor(InternalResourceManager.java:343)
at
org.apache.geode.internal.cache.control.InternalResourceManager.close(InternalResourceManager.java:156)
at
org.apache.geode.internal.cache.GemFireCacheImpl.close(GemFireCacheImpl.java:2079)
- locked <0x0000000766665b58> (a java.lang.Class for
org.apache.geode.internal.cache.GemFireCacheImpl)
at
org.apache.geode.distributed.internal.InternalDistributedSystem.disconnect(InternalDistributedSystem.java:1516)
- locked <0x0000000766665b58> (a java.lang.Class for
org.apache.geode.internal.cache.GemFireCacheImpl)
at
org.apache.geode.distributed.internal.InternalDistributedSystem.lambda$static$6(InternalDistributedSystem.java:2181)
at
org.apache.geode.distributed.internal.InternalDistributedSystem$$Lambda$8/111900554.run(Unknown
Source)
at java.lang.Thread.run(Thread.java:745)
{noformat}
InternalResourceManager.stopExecutor waits up to 120 seconds to stop:
{noformat}
void stopExecutor(ExecutorService executor) {
if (executor == null) {
return;
}
executor.shutdown();
final int secToWait = Integer
.getInteger(DistributionConfig.GEMFIRE_PREFIX +
"prrecovery-close-timeout", 120).intValue();
try {
executor.awaitTermination(secToWait, TimeUnit.SECONDS);
} catch (InterruptedException x) {
Thread.currentThread().interrupt();
logger.debug("Failed in interrupting the Resource Manager Thread due to
interrupt");
}
if (!executor.isTerminated()) {
logger.warn("Failed to stop resource manager threads in {} seconds",
secToWait);
}
}
{noformat}
I added some logging that shows the sequence of events.
The logging shows the redundancy recovery task being scheduled when the first
server is killed (steps 3 and 4 above):
{noformat}
[warn 2019/06/24 14:09:21.014 PDT <DM-MemberEventInvoker> tid=0x15]
PRHARedundancyProvider.scheduleRedundancyRecovery about to schedule task with
delay=30000
{noformat}
Then, the shutdown hook is invoked when the server is stopped which causes the
InternalResourceManager to wait. The 1 task below is the redundancy recovery
task:
{noformat}
[info 2019/06/24 14:09:25.161 PDT <Distributed system shutdown hook> tid=0xc]
VM is exiting - shutting down distributed system
[info 2019/06/24 14:09:25.173 PDT <Distributed system shutdown hook> tid=0xc]
GemFireCache[id = 1850680894; isClosing = true; isShutDownAll = false; created
= Mon Jun 24 14:08:40 PDT 2019; server = false; copyOnRead = false; lockLease =
120; lockTimeout = 60]: Now closing.
[warn 2019/06/24 14:09:25.174 PDT <Distributed system shutdown hook> tid=0xc]
InternalResourceManager.stopExecutor waiting up to 120 seconds to terminate
ScheduledThreadPoolExecutor containing 1 task
{noformat}
Then, the redundancy recovery task attempts to execute, but a
CacheClosedException is thrown, so it doesn't do anything:
{noformat}
[warn 2019/06/24 14:09:51.016 PDT <ResourceManagerRecoveryThread 1> tid=0xb2]
PRHARedundancyProvider.run2 about to start recovery
[warn 2019/06/24 14:09:51.016 PDT <ResourceManagerRecoveryThread 1> tid=0xb2]
PRHARedundancyProvider.run2 caught:
org.apache.geode.cache.CacheClosedException: The cache is closed.
at
org.apache.geode.internal.cache.GemFireCacheImpl$Stopper.generateCancelledException(GemFireCacheImpl.java:1482)
at
org.apache.geode.CancelCriterion.checkCancelInProgress(CancelCriterion.java:83)
at
org.apache.geode.internal.cache.GemFireCacheImpl.getInternalResourceManager(GemFireCacheImpl.java:4302)
at
org.apache.geode.internal.cache.GemFireCacheImpl.getResourceManager(GemFireCacheImpl.java:4291)
at
org.apache.geode.internal.cache.control.InternalResourceManager.getInternalResourceManager(InternalResourceManager.java:102)
at
org.apache.geode.internal.cache.partitioned.PartitionedRegionRebalanceOp.execute(PartitionedRegionRebalanceOp.java:154)
at
org.apache.geode.internal.cache.PRHARedundancyProvider$3.run2(PRHARedundancyProvider.java:1600)
at
org.apache.geode.internal.cache.partitioned.RecoveryRunnable.run(RecoveryRunnable.java:59)
at
org.apache.geode.internal.OneTaskOnlyExecutor$DelegatingRunnable.run(OneTaskOnlyExecutor.java:142)
at
java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at
java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)
at
java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:745)
{noformat}
Finally, the InternalResourceManager stops the executor:
{noformat}
[warn 2019/06/24 14:09:51.018 PDT <Distributed system shutdown hook> tid=0xc]
InternalResourceManager.stopExecutor terminated
{noformat}
It looks like there are a few things that can be done to address this:
1. Don't wait to shutdown the executor. Just shut it down immediately. I'm not
sure the consequences of this. In the above case, I'm not sure there are any,
but there are other cases.
2. Don't schedule the redundancy recovery task for sometime in the future. Wait
for the future to arrive and then schedule it. Darrel suggested this in one of
his comments.
> The InternalResourceManager fails to shutdown if a redundancy recovery task
> is scheduled but hasn't fired yet
> -------------------------------------------------------------------------------------------------------------
>
> Key: GEODE-3718
> URL: https://issues.apache.org/jira/browse/GEODE-3718
> Project: Geode
> Issue Type: Bug
> Components: core
> Reporter: Barry Oglesby
> Assignee: Mario Ivanac
> Priority: Major
> Labels: needs-review, pull-request-available, recovery
> Time Spent: 40m
> Remaining Estimate: 0h
>
> This happens with recovery-delay or startup-recovery-delay > 0.
> The thread gets stuck here:
> {noformat}
> "Thread-20" #133 prio=10 os_prio=31 tid=0x00007fa85b886000 nid=0x890b waiting
> on condition [0x000070001269e000]
> java.lang.Thread.State: TIMED_WAITING (parking)
> at sun.misc.Unsafe.park(Native Method)
> - parking to wait for <0x00000007bc408900> (a
> java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
> at
> java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
> at
> java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2078)
> at
> java.util.concurrent.ThreadPoolExecutor.awaitTermination(ThreadPoolExecutor.java:1465)
> at
> org.apache.geode.internal.cache.control.InternalResourceManager.stopExecutor(InternalResourceManager.java:375)
> at
> org.apache.geode.internal.cache.control.InternalResourceManager.close(InternalResourceManager.java:187)
> at
> org.apache.geode.internal.cache.GemFireCacheImpl.close(GemFireCacheImpl.java:2161)
> - locked <0x00000007bc0bc520> (a java.lang.Class for
> org.apache.geode.internal.cache.GemFireCacheImpl)
> at
> org.apache.geode.distributed.internal.InternalDistributedSystem.disconnect(InternalDistributedSystem.java:1367)
> - locked <0x00000007bc0bc520> (a java.lang.Class for
> org.apache.geode.internal.cache.GemFireCacheImpl)
> at
> org.apache.geode.distributed.internal.InternalDistributedSystem.disconnect(InternalDistributedSystem.java:1017)
> at
> org.apache.geode.management.internal.beans.MemberMBeanBridge$1.run(MemberMBeanBridge.java:986)
> at java.lang.Thread.run(Thread.java:745)
> {noformat}
> The InternalResourceManager is waiting for the termination of its
> scheduledExecutor.
> The PRHARedundancyProvider initializes its recoveryExecutor using the
> InternalResourceManager's scheduledExecutor:
> {noformat}
> recoveryExecutor = new OneTaskOnlyExecutor(resourceManager.getExecutor(),
> new OneTaskOnlyExecutor.ConflatedTaskListener() {
> public void taskDropped() {
> InternalResourceManager.getResourceObserver().recoveryConflated(region);
> }
> });
> {noformat}
> The scheduleRedundancyRecovery method schedules a RecoveryRunnable if
> necessary.
> If that task hasn't fired yet, the InternalResourceManager doesn't close, and
> the JVM stays up.
--
This message was sent by Atlassian JIRA
(v7.6.3#76005)
