[
https://issues.apache.org/jira/browse/GEODE-6435?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16773584#comment-16773584
]
Barry Oglesby commented on GEODE-6435:
--------------------------------------
Several threads in vm4 are throwing OutOfMemoryErrors in this test.
{noformat}
[vm4] java.lang.OutOfMemoryError: Java heap space
[vm4] Dumping heap to java_pid367.hprof ...
[vm4] Heap dump file created [558837052 bytes in 1.626 secs]
[vm4] [fatal 2019/02/20 01:51:58.219 UTC <Asynchronous disk writer for region
ln-62> tid=0x8ba] Fatal error from asynchronous flusher thread
[vm4] java.lang.OutOfMemoryError: Java heap space
[vm4] [error 2019/02/20 01:51:58.232 UTC <unicast receiver,2e6d9f20266c-48305>
tid=0x6ac] JGRP000190: failed receiving packet
[vm4] java.lang.OutOfMemoryError: Java heap space
[vm4] [fatal 2019/02/20 01:51:59.303 UTC <Asynchronous disk writer for region
ln-54> tid=0x87a] Fatal error from asynchronous flusher thread
[vm4] java.lang.OutOfMemoryError: Java heap space
[vm4] [fatal 2019/02/20 01:51:59.303 UTC <Asynchronous disk writer for region
ln-19> tid=0x760] Fatal error from asynchronous flusher thread
[vm4] java.lang.OutOfMemoryError: Java heap space
[vm4] [fatal 2019/02/20 01:51:59.303 UTC <Asynchronous disk writer for region
ln-55> tid=0x882] Fatal error from asynchronous flusher thread
[vm4] java.lang.OutOfMemoryError: Java heap space
[vm4] [fatal 2019/02/20 01:51:59.304 UTC <Asynchronous disk writer for region
ln-106> tid=0xa23] Fatal error from asynchronous flusher thread
[vm4] java.lang.OutOfMemoryError: Java heap space
{noformat}
When I run the test on my local machine, it is successful. The difference is
that my test runs in ~7 seconds. The failed test took ~10 seconds. This is
enough time for the PingTask to run. This creates an additional connection (so
it doubles the connections).
A stack trace shows the PingTask creating a Connection:
{noformat}
[vm4] java.lang.Exception: Stack trace
[vm4] at java.base/java.lang.Thread.dumpStack(Thread.java:1387)
[vm4] at
org.apache.geode.cache.client.internal.ConnectionImpl.connect(ConnectionImpl.java:112)
[vm4] at
org.apache.geode.cache.client.internal.ConnectionConnector.connectClientToServer(ConnectionConnector.java:75)
[vm4] at
org.apache.geode.cache.client.internal.ConnectionFactoryImpl.createClientToServerConnection(ConnectionFactoryImpl.java:111)
[vm4] at
org.apache.geode.cache.client.internal.pooling.ConnectionManagerImpl.borrowConnection(ConnectionManagerImpl.java:321)
[vm4] at
org.apache.geode.cache.client.internal.OpExecutorImpl.executeOnServer(OpExecutorImpl.java:395)
[vm4] at
org.apache.geode.cache.client.internal.OpExecutorImpl.executeOn(OpExecutorImpl.java:362)
[vm4] at
org.apache.geode.cache.client.internal.PoolImpl.executeOn(PoolImpl.java:835)
[vm4] at org.apache.geode.cache.client.internal.PingOp.execute(PingOp.java:36)
[vm4] at
org.apache.geode.cache.client.internal.LiveServerPinger$PingTask.run2(LiveServerPinger.java:90)
[vm4] at
org.apache.geode.cache.client.internal.PoolImpl$PoolTask.run(PoolImpl.java:1371)
[vm4] at
java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
[vm4] at
java.base/java.util.concurrent.FutureTask.runAndReset(FutureTask.java:305)
[vm4] at
org.apache.geode.internal.ScheduledThreadPoolExecutorWithKeepAlive$DelegatingScheduledFuture.run(ScheduledThreadPoolExecutorWithKeepAlive.java:276)
[vm4] at
java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
[vm4] at
java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
[vm4] at java.base/java.lang.Thread.run(Thread.java:834)
{noformat}
In the failed test, there are log messages from the poolTimer threads like
below. These are coming from the PingTask threads.
{noformat}
[vm4] [info 2019/02/20 01:51:02.547 UTC <poolTimer-ln-46-4> tid=0xaa0] Socket
receive buffer size is 212992 instead of the requested 524288.
[vm4] [info 2019/02/20 01:51:02.547 UTC <poolTimer-ln-46-4> tid=0xaa0] Socket
send buffer size is 212992 instead of the requested 524288.
[vm4] [info 2019/02/20 01:51:02.607 UTC <poolTimer-ln-47-4> tid=0xaa1] Socket
receive buffer size is 212992 instead of the requested 524288.
[vm4] [info 2019/02/20 01:51:02.608 UTC <poolTimer-ln-47-4> tid=0xaa1] Socket
send buffer size is 212992 instead of the requested 524288.
[vm4] [info 2019/02/20 01:51:02.657 UTC <poolTimer-ln-48-4> tid=0xaa2] Socket
receive buffer size is 212992 instead of the requested 524288.
[vm4] [info 2019/02/20 01:51:02.657 UTC <poolTimer-ln-48-4> tid=0xaa2] Socket
send buffer size is 212992 instead of the requested 524288.
[vm4] [info 2019/02/20 01:51:02.727 UTC <poolTimer-ln-50-6> tid=0xaa4] Socket
receive buffer size is 212992 instead of the requested 524288.
[vm4] [info 2019/02/20 01:51:02.727 UTC <poolTimer-ln-50-6> tid=0xaa4] Socket
send buffer size is 212992 instead of the requested 524288.
...
{noformat}
If I add a sleep in the test to mimic the CI test run, my test throws the same
OutOfMemoryErrors.
This test does not behave the same way in JDK 8. It uses much less memory.
I attached a few charts showing the memory usage in both JDK 8 and JDK 11 with
successful and failed tests.
> CI Failure: SerialGatewaySenderQueueDUnitTest.testCreateMaximumSenders
> assertion fails
> --------------------------------------------------------------------------------------
>
> Key: GEODE-6435
> URL: https://issues.apache.org/jira/browse/GEODE-6435
> Project: Geode
> Issue Type: Bug
> Reporter: Patrick Rhomberg
> Assignee: Barry Oglesby
> Priority: Major
> Attachments: jdk11_OldGen_usedMemory_failure.gif,
> jdk11_OldGen_usedMemory_success.gif, jdk8_OldGen_usedMemory_success.gif
>
>
> {noformat}
> org.apache.geode.internal.cache.wan.serial.SerialGatewaySenderQueueDUnitTest
> > testCreateMaximumSenders FAILED
> org.apache.geode.test.dunit.RMIException: While invoking
> org.apache.geode.internal.cache.wan.serial.SerialGatewaySenderQueueDUnitTest$$Lambda$390/0x0000000840596840.run
> in VM 2 running on Host 2e6d9f20266c with 8 VMs
> at org.apache.geode.test.dunit.VM.executeMethodOnObject(VM.java:579)
> at org.apache.geode.test.dunit.VM.invoke(VM.java:406)
> at
> org.apache.geode.internal.cache.wan.serial.SerialGatewaySenderQueueDUnitTest.testCreateMaximumSenders(SerialGatewaySenderQueueDUnitTest.java:370)
> Caused by:
> org.awaitility.core.ConditionTimeoutException: Condition with lambda
> expression in org.apache.geode.internal.cache.wan.WANTestBase that uses long
> was not fulfilled within 300 seconds.
> at
> org.awaitility.core.ConditionAwaiter.await(ConditionAwaiter.java:145)
> at
> org.awaitility.core.CallableCondition.await(CallableCondition.java:79)
> at
> org.awaitility.core.CallableCondition.await(CallableCondition.java:27)
> at
> org.awaitility.core.ConditionFactory.until(ConditionFactory.java:902)
> at
> org.awaitility.core.ConditionFactory.until(ConditionFactory.java:860)
> at
> org.apache.geode.internal.cache.wan.WANTestBase.verifyListenerEvents(WANTestBase.java:3542)
> at
> org.apache.geode.internal.cache.wan.serial.SerialGatewaySenderQueueDUnitTest.lambda$testCreateMaximumSenders$faf964a3$1(SerialGatewaySenderQueueDUnitTest.java:370)
> java.lang.AssertionError: An exception occurred during asynchronous
> invocation.
> Caused by:
> java.rmi.ConnectIOException: error during JRMP connection
> establishment; nested exception is:
> java.net.SocketTimeoutException: Read timed out
> Caused by:
> java.net.SocketTimeoutException: Read timed out
> {noformat}
>
> See pipeline failure here:
> [https://concourse.apachegeode-ci.info/teams/main/pipelines/apache-develop-main/jobs/DistributedTestOpenJDK11/builds/413]
> Find test results here:
> [http://files.apachegeode-ci.info/builds/apache-develop-main/1.9.0-SNAPSHOT.0456/test-results/distributedTest/1550631451/]
> Find artifacts here:
> [http://files.apachegeode-ci.info/builds/apache-develop-main/1.9.0-SNAPSHOT.0456/test-artifacts/1550631451/distributedtestfiles-OpenJDK11-1.9.0-SNAPSHOT.0456.tgz]
>
--
This message was sent by Atlassian JIRA
(v7.6.3#76005)
