geode-issues mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Bruce J Schuchardt (Jira)" <j...@apache.org>
Subject [jira] [Created] (GEODE-7310) CI failure: hang in IncrementalBackupDistributedTest.testIncompleteInBaseline
Date Wed, 16 Oct 2019 15:55:00 GMT
Bruce J Schuchardt created GEODE-7310:
-----------------------------------------

             Summary: CI failure: hang in IncrementalBackupDistributedTest.testIncompleteInBaseline
                 Key: GEODE-7310
                 URL: https://issues.apache.org/jira/browse/GEODE-7310
             Project: Geode
          Issue Type: Improvement
          Components: persistence
            Reporter: Bruce J Schuchardt


At least three distributed unit test runs have recently hung in this test.

https://concourse.apachegeode-ci.info/teams/main/pipelines/apache-develop-main/jobs/DistributedTestOpenJDK11/builds/1158
https://concourse.apachegeode-ci.info/teams/main/pipelines/apache-develop-main/jobs/DistributedTestOpenJDK11/builds/1164
and
https://concourse.apachegeode-ci.info/teams/main/pipelines/apache-develop-main/jobs/DistributedTestOpenJDK11/builds/1172

Here are some threads that might be of interest in the latest hang:

{noformat}
   java.lang.Thread.State: RUNNABLE
	at java.net.SocketInputStream.socketRead0(java.base@11.0.4/Native Method)
	at java.net.SocketInputStream.socketRead(java.base@11.0.4/SocketInputStream.java:115)
	at java.net.SocketInputStream.read(java.base@11.0.4/SocketInputStream.java:168)
	at java.net.SocketInputStream.read(java.base@11.0.4/SocketInputStream.java:140)
	at java.io.BufferedInputStream.fill(java.base@11.0.4/BufferedInputStream.java:252)
	at java.io.BufferedInputStream.read(java.base@11.0.4/BufferedInputStream.java:271)
	- locked <0x00000000e3c4e9b8> (a java.io.BufferedInputStream)
	at java.io.DataInputStream.readByte(java.base@11.0.4/DataInputStream.java:270)
	at sun.rmi.transport.StreamRemoteCall.executeCall(java.rmi@11.0.4/StreamRemoteCall.java:222)
	at sun.rmi.server.UnicastRef.invoke(java.rmi@11.0.4/UnicastRef.java:161)
	at java.rmi.server.RemoteObjectInvocationHandler.invokeRemoteMethod(java.rmi@11.0.4/RemoteObjectInvocationHandler.java:209)
	at java.rmi.server.RemoteObjectInvocationHandler.invoke(java.rmi@11.0.4/RemoteObjectInvocationHandler.java:161)
	at com.sun.proxy.$Proxy55.executeMethodOnObject(Unknown Source)
	at org.apache.geode.test.dunit.VM.executeMethodOnObject(VM.java:576)
	at org.apache.geode.test.dunit.VM.invoke(VM.java:431)
	at org.apache.geode.internal.cache.backup.IncrementalBackupDistributedTest.testIncompleteInBaseline(IncrementalBackupDistributedTest.java:327)

"RMI TCP Connection(4)-172.17.0.9" #40 daemon prio=5 os_prio=0 cpu=1139.47ms elapsed=4212.37s
tid=0x00007f2f94004800 nid=0x1f7 waiting on condition  [0x00007f301d826000]
   java.lang.Thread.State: TIMED_WAITING (parking)
	at jdk.internal.misc.Unsafe.park(java.base@11.0.4/Native Method)
	- parking to wait for  <0x00000000ecf14698> (a java.util.concurrent.CountDownLatch$Sync)
	at java.util.concurrent.locks.LockSupport.parkNanos(java.base@11.0.4/LockSupport.java:234)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedNanos(java.base@11.0.4/AbstractQueuedSynchronizer.java:1079)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer.tryAcquireSharedNanos(java.base@11.0.4/AbstractQueuedSynchronizer.java:1369)
	at java.util.concurrent.CountDownLatch.await(java.base@11.0.4/CountDownLatch.java:278)
	at org.apache.geode.internal.util.concurrent.StoppableCountDownLatch.awaitWithCheck(StoppableCountDownLatch.java:120)
	at org.apache.geode.internal.util.concurrent.StoppableCountDownLatch.await(StoppableCountDownLatch.java:93)
	at org.apache.geode.distributed.internal.ReplyProcessor21.basicWait(ReplyProcessor21.java:692)
	at org.apache.geode.distributed.internal.ReplyProcessor21.waitForReplies(ReplyProcessor21.java:639)
	at org.apache.geode.distributed.internal.ReplyProcessor21.waitForReplies(ReplyProcessor21.java:620)
	at org.apache.geode.distributed.internal.ReplyProcessor21.waitForReplies(ReplyProcessor21.java:534)
	at org.apache.geode.internal.cache.backup.BackupStep.send(BackupStep.java:66)
	at org.apache.geode.internal.cache.backup.BackupOperation.performBackupSteps(BackupOperation.java:121)
	at org.apache.geode.internal.cache.backup.BackupOperation.performBackupUnderLock(BackupOperation.java:92)
	at org.apache.geode.internal.cache.backup.BackupOperation.performBackup(BackupOperation.java:77)
	at org.apache.geode.internal.cache.backup.BackupOperation.backupAllMembers(BackupOperation.java:71)
	at org.apache.geode.internal.cache.backup.IncrementalBackupDistributedTest.performBackup(IncrementalBackupDistributedTest.java:565)
	at org.apache.geode.internal.cache.backup.IncrementalBackupDistributedTest.performBackup(IncrementalBackupDistributedTest.java:560)
	at org.apache.geode.internal.cache.backup.IncrementalBackupDistributedTest.lambda$testIncompleteInBaseline$515fd116$1(IncrementalBackupDistributedTest.java:327)
	at org.apache.geode.internal.cache.backup.IncrementalBackupDistributedTest$$Lambda$418/0x0000000840c20c40.call(Unknown
Source)

"BackupServiceThread1" #276 daemon prio=10 os_prio=0 cpu=0.33ms elapsed=4152.24s tid=0x00007f377021b000
nid=0x50c waiting on condition  [0x00007f38391d6000]
   java.lang.Thread.State: WAITING (parking)
	at jdk.internal.misc.Unsafe.park(java.base@11.0.4/Native Method)
	- parking to wait for  <0x00000000e3ce6438> (a java.util.concurrent.CountDownLatch$Sync)
	at java.util.concurrent.locks.LockSupport.park(java.base@11.0.4/LockSupport.java:194)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(java.base@11.0.4/AbstractQueuedSynchronizer.java:885)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedInterruptibly(java.base@11.0.4/AbstractQueuedSynchronizer.java:1039)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(java.base@11.0.4/AbstractQueuedSynchronizer.java:1345)
	at java.util.concurrent.CountDownLatch.await(java.base@11.0.4/CountDownLatch.java:232)
	at org.apache.geode.internal.cache.backup.BackupTask.backup(BackupTask.java:72)
	at org.apache.geode.internal.cache.backup.BackupService.lambda$prepareBackup$0(BackupService.java:62)
	at org.apache.geode.internal.cache.backup.BackupService$$Lambda$406/0x0000000840c48040.call(Unknown
Source)
	at java.util.concurrent.FutureTask.run(java.base@11.0.4/FutureTask.java:264)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@11.0.4/ThreadPoolExecutor.java:1128)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@11.0.4/ThreadPoolExecutor.java:628)
	at java.lang.Thread.run(java.base@11.0.4/Thread.java:834)

"BackupServiceThread1" #266 daemon prio=5 os_prio=0 cpu=0.43ms elapsed=4156.14s tid=0x00007f2fac631800
nid=0x50e waiting on condition  [0x00007f2f455c7000]
   java.lang.Thread.State: WAITING (parking)
	at jdk.internal.misc.Unsafe.park(java.base@11.0.4/Native Method)
	- parking to wait for  <0x00000000ecf518b8> (a java.util.concurrent.CountDownLatch$Sync)
	at java.util.concurrent.locks.LockSupport.park(java.base@11.0.4/LockSupport.java:194)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(java.base@11.0.4/AbstractQueuedSynchronizer.java:885)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedInterruptibly(java.base@11.0.4/AbstractQueuedSynchronizer.java:1039)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(java.base@11.0.4/AbstractQueuedSynchronizer.java:1345)
	at java.util.concurrent.CountDownLatch.await(java.base@11.0.4/CountDownLatch.java:232)
	at org.apache.geode.internal.cache.backup.BackupTask.backup(BackupTask.java:72)
	at org.apache.geode.internal.cache.backup.BackupService.lambda$prepareBackup$0(BackupService.java:62)
	at org.apache.geode.internal.cache.backup.BackupService$$Lambda$390/0x0000000840be0c40.call(Unknown
Source)
	at java.util.concurrent.FutureTask.run(java.base@11.0.4/FutureTask.java:264)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@11.0.4/ThreadPoolExecutor.java:1128)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@11.0.4/ThreadPoolExecutor.java:628)
	at java.lang.Thread.run(java.base@11.0.4/Thread.java:834)

   Locked ownable synchronizers:
	- <0x00000000ece9fc10> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)
	- <0x00000000eceb37b0> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)
	- <0x00000000ecf51990> (a java.util.concurrent.ThreadPoolExecutor$Worker)


"Pooled Message Processor 3" #86 daemon prio=10 os_prio=0 cpu=41.38ms elapsed=4176.70s tid=0x00007fcfb403f800
nid=0x307 waiting on condition  [0x00007fd0348d4000]
   java.lang.Thread.State: WAITING (parking)
	at jdk.internal.misc.Unsafe.park(java.base@11.0.4/Native Method)
	- parking to wait for  <0x00000000ecf68520> (a java.util.concurrent.CountDownLatch$Sync)
	at java.util.concurrent.locks.LockSupport.park(java.base@11.0.4/LockSupport.java:194)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(java.base@11.0.4/AbstractQueuedSynchronizer.java:885)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedInterruptibly(java.base@11.0.4/AbstractQueuedSynchronizer.java:1039)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(java.base@11.0.4/AbstractQueuedSynchronizer.java:1345)
	at java.util.concurrent.CountDownLatch.await(java.base@11.0.4/CountDownLatch.java:232)
	at org.apache.geode.internal.cache.backup.BackupTask.getPreparedDiskStores(BackupTask.java:60)
	at org.apache.geode.internal.cache.backup.BackupService.prepareBackup(BackupService.java:63)
	at org.apache.geode.internal.cache.backup.PrepareBackup.run(PrepareBackup.java:41)
	at org.apache.geode.internal.cache.backup.PrepareBackupRequest.createResponse(PrepareBackupRequest.java:66)
	at org.apache.geode.internal.admin.remote.CliLegacyMessage.process(CliLegacyMessage.java:37)
	at org.apache.geode.distributed.internal.DistributionMessage.scheduleAction(DistributionMessage.java:372)
	at org.apache.geode.distributed.internal.DistributionMessage$1.run(DistributionMessage.java:436)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@11.0.4/ThreadPoolExecutor.java:1128)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@11.0.4/ThreadPoolExecutor.java:628)
	at org.apache.geode.distributed.internal.ClusterOperationExecutors.runUntilShutdown(ClusterOperationExecutors.java:475)
	at org.apache.geode.distributed.internal.ClusterOperationExecutors.doProcessingThread(ClusterOperationExecutors.java:406)
	at org.apache.geode.distributed.internal.ClusterOperationExecutors$$Lambda$174/0x0000000840a39840.invoke(Unknown
Source)
	at org.apache.geode.internal.logging.LoggingThreadFactory.lambda$newThread$0(LoggingThreadFactory.java:119)
	at org.apache.geode.internal.logging.LoggingThreadFactory$$Lambda$175/0x0000000840a39c40.run(Unknown
Source)
	at java.lang.Thread.run(java.base@11.0.4/Thread.java:834)

{noformat}

Test output shows these as the last log entries written to logs & captured by gradle:

{noformat}
[vm0] [info 2019/10/15 22:40:23.697 GMT <Pooled Waiting Message Processor 1> tid=0xd0]
Configured redundancy of 1 copies has been restored to /IncrementalBackupDistributedTest_testIncompleteInBaseline_region-2

[info 2019/10/15 22:40:23.698 GMT <Pooled Waiting Message Processor 1> tid=0xf1] Configured
redundancy of 1 copies has been restored to /IncrementalBackupDistributedTest_testIncompleteInBaseline_region-2

[vm1] [info 2019/10/15 22:40:26.230 GMT <RMI TCP Connection(4)-172.17.0.9> tid=0x28]
Received method: org.apache.geode.internal.cache.backup.IncrementalBackupDistributedTest$$Lambda$417/0x0000000840c20840.call
with 0 args on object: org.apache.geode.internal.cache.backup.IncrementalBackupDistributedTest$$Lambda$417/0x0000000840c20840@2aba62dc
[vm1] [info 2019/10/15 22:40:26.230 GMT <RMI TCP Connection(4)-172.17.0.9> tid=0x28]
Received method: org.apache.geode.internal.cache.backup.IncrementalBackupDistributedTest$$Lambda$417/0x0000000840c20840.call
with 0 args on object: org.apache.geode.internal.cache.backup.IncrementalBackupDistributedTest$$Lambda$417/0x0000000840c20840@2aba62dc
[vm1] [info 2019/10/15 22:40:26.240 GMT <RMI TCP Connection(4)-172.17.0.9> tid=0x28]
Received method: org.apache.geode.internal.cache.backup.IncrementalBackupDistributedTest$$Lambda$418/0x0000000840c20c40.call
with 0 args on object: org.apache.geode.internal.cache.backup.IncrementalBackupDistributedTest$$Lambda$418/0x0000000840c20c40@6eaf6978
{noformat}





--
This message was sent by Atlassian Jira
(v8.3.4#803005)

Mime
View raw message