JDK-8223739 : serviceability/dcmd/gc/HeapDumpAllTest.java timeout with Graal
Type:Bug
Component:hotspot
Sub-Component:compiler
Affected Version:13
Priority:P3
Status:Closed
Resolution:Duplicate
Submitted:2019-05-11
Updated:2020-08-07
Resolved:2020-08-07
The Version table provides details related to the release that this issue/RFE will be addressed.
Unresolved : Release in which this issue/RFE will be addressed. Resolved: Release in which this issue/RFE has been resolved. Fixed : Release in which this issue/RFE has been fixed. The release containing this fix may be available for download as an Early Access Release or a General Availability Release.
The run times for this test vary widely, but as a rule, it seems to run an order of magnitude slower with Graal, and occasionally times out.
Comments
Closing as a duplicate of JDK-8196611.
07-08-2020
We are seeing the same issue with 11. Here is a stack trace of which I think is the problem:
"AgentVMThread" #31 prio=5 os_prio=0 cpu=454294.32ms elapsed=480.74s tid=0x00007f4f3855e800 nid=0x6a4bb runnable [0x00007f4ef93ff000]
java.lang.Thread.State: RUNNABLE
JavaThread state: _thread_blocked
Thread: 0x00007f4f3855e800 [0x6a4bb] State: _call_back _has_called_back 1 _at_poll_safepoint 0
JavaThread state: _thread_blocked
at java.io.RandomAccessFile.read0(java.base@11.0.6.0.3-internal/Native Method)
at java.io.RandomAccessFile.read(java.base@11.0.6.0.3-internal/RandomAccessFile.java:366)
at java.io.RandomAccessFile.readInt(java.base@11.0.6.0.3-internal/RandomAccessFile.java:835)
at java.io.RandomAccessFile.readLong(java.base@11.0.6.0.3-internal/RandomAccessFile.java:870)
at jdk.test.lib.hprof.parser.FileReadBuffer.getLong(FileReadBuffer.java:87)
- locked <0x00000005f2d82d00> (a jdk.test.lib.hprof.parser.FileReadBuffer)
at jdk.test.lib.hprof.model.JavaLazyReadObject.longAt(JavaLazyReadObject.java:156)
at jdk.test.lib.hprof.model.JavaLazyReadObject.objectIdAt(JavaLazyReadObject.java:130)
at jdk.test.lib.hprof.model.JavaObject.parseFields(JavaObject.java:263)
at jdk.test.lib.hprof.model.JavaObject.getFields(JavaObject.java:117)
at jdk.test.lib.hprof.model.JavaObject.visitReferencedObjects(JavaObject.java:142)
at jdk.test.lib.hprof.model.Snapshot.calculateReferencesToObjects(Snapshot.java:323)
at jdk.test.lib.hprof.model.Snapshot.resolve(Snapshot.java:291)
at jdk.test.lib.hprof.HprofParser.parse(HprofParser.java:87)
at jdk.test.lib.hprof.HprofParser.parse(HprofParser.java:54)
at HeapDumpTest.verifyHeapDump(HeapDumpTest.java:69)
at HeapDumpTest.run(HeapDumpTest.java:62)
at HeapDumpTest.pid(HeapDumpTest.java:88)
at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(java.base@11.0.6.0.3-internal/Native Method)
at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(java.base@11.0.6.0.3-internal/NativeMethodAccessorImpl.java:62)
at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(java.base@11.0.6.0.3-internal/DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(java.base@11.0.6.0.3-internal/Method.java:566)
at org.testng.internal.MethodInvocationHelper.invokeMethod(MethodInvocationHelper.java:85)
at org.testng.internal.Invoker.invokeMethod(Invoker.java:639)
at org.testng.internal.Invoker.invokeTestMethod(Invoker.java:821)
at org.testng.internal.Invoker.invokeTestMethods(Invoker.java:1131)
at org.testng.internal.TestMethodWorker.invokeTestMethods(TestMethodWorker.java:125)
at org.testng.internal.TestMethodWorker.run(TestMethodWorker.java:108)
at org.testng.TestRunner.privateRun(TestRunner.java:773)
at org.testng.TestRunner.run(TestRunner.java:623)
at org.testng.SuiteRunner.runTest(SuiteRunner.java:357)
at org.testng.SuiteRunner.runSequentially(SuiteRunner.java:352)
at org.testng.SuiteRunner.privateRun(SuiteRunner.java:310)
at org.testng.SuiteRunner.run(SuiteRunner.java:259)
at org.testng.SuiteRunnerWorker.runSuite(SuiteRunnerWorker.java:52)
at org.testng.SuiteRunnerWorker.run(SuiteRunnerWorker.java:86)
at org.testng.TestNG.runSuitesSequentially(TestNG.java:1185)
at org.testng.TestNG.runSuitesLocally(TestNG.java:1110)
at org.testng.TestNG.run(TestNG.java:1018)
at com.sun.javatest.regtest.agent.TestNGRunner.main(TestNGRunner.java:94)
at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(java.base@11.0.6.0.3-internal/Native Method)
at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(java.base@11.0.6.0.3-internal/NativeMethodAccessorImpl.java:62)
at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(java.base@11.0.6.0.3-internal/DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(java.base@11.0.6.0.3-internal/Method.java:566)
at com.sun.javatest.regtest.agent.MainActionHelper$AgentVMRunnable.run(MainActionHelper.java:298)
at java.lang.Thread.run(java.base@11.0.6.0.3-internal/Thread.java:834)
I don't see the "Snapshot read, resolving..." output in our log files.
27-02-2020
Marking this as test bug for now. Please remove the label if it turns out to be a Graal issue.
22-11-2019
When I run this test by itself, I get:
Dump file created Fri Aug 16 16:33:44 EDT 2019
Snapshot read, resolving...
Resolving 236204 objects...
Chasing references, expect 47 dots...............................................
Eliminating duplicate references...............................................
Snapshot resolved.
but for jobs the timed out, the numbers are much bigger:
Dump file created Thu Jun 27 19:10:32 GMT 2019
Snapshot read, resolving...
Resolving 10813009 objects...
Chasing references, expect 2162 dots [...]
17-08-2019
Almost all of the time seems to be in the call to HprofParser.parse(). How does Graal affect this? Maybe it's just an increased number of object in the heap because of Graal compiles?