JDK-8258512 : serviceability/sa/TestJmapCore.java timed out on macOS 10.13.6
  • Type: Bug
  • Component: hotspot
  • Sub-Component: svc-agent
  • Affected Version: 16
  • Priority: P4
  • Status: Resolved
  • Resolution: Fixed
  • OS: os_x
  • CPU: x86_64
  • Submitted: 2020-12-16
  • Updated: 2023-01-02
  • Resolved: 2021-12-02
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.

To download the current JDK release, click here.
JDK 17 JDK 18
17.0.7-oracleFixed 18 b27Fixed
Related Reports
Relates :  
JDK-8214797 - TestJmapCoreMetaspace.java timed out
Description
The following test timed out:

serviceability/sa/TestJmapCore.java

Here's a snippet from the log file:

----------System.out:(42/4333)----------
Command line: [/mesos/work_dir/jib-master/install/jdk-16+29-2089/macosx-x64-debug.jdk/jdk-16/fastdebug/bin/java -cp /mesos/work_dir/slaves/4076d11c-c6ed-4d07-84c1-4ab8d55cd975-S149862/frameworks/1735e8a2-a1db-478c-8104-60c8b0af87dd-0196/executors/b205764e-ee1a-4ca9-9215-5fec653c9eac/runs/464ec356-619e-44bf-9247-f85dd796f8af/testoutput/test-support/jtreg_open_test_hotspot_jtreg_serviceability_sa/classes/1/serviceability/sa/TestJmapCore.d:/mesos/work_dir/jib-master/install/jdk-16+29-2089/src.full/open/test/hotspot/jtreg/serviceability/sa:/mesos/work_dir/slaves/4076d11c-c6ed-4d07-84c1-4ab8d55cd975-S149862/frameworks/1735e8a2-a1db-478c-8104-60c8b0af87dd-0196/executors/b205764e-ee1a-4ca9-9215-5fec653c9eac/runs/464ec356-619e-44bf-9247-f85dd796f8af/testoutput/test-support/jtreg_open_test_hotspot_jtreg_serviceability_sa/classes/1/test/lib:/mesos/work_dir/jib-master/install/jtreg/5.1/b01/bundles/jtreg_bin-5.1.zip/jtreg/lib/javatest.jar:/mesos/work_dir/jib-master/install/jtreg/5.1/b01/bundles/jtreg_bin-5.1.zip/jtreg/lib/jtreg.jar:/mesos/work_dir/jib-master/install/jtreg/5.1/b01/bundles/jtreg_bin-5.1.zip/jtreg/lib/junit.jar:/mesos/work_dir/jib-master/install/jtreg/5.1/b01/bundles/jtreg_bin-5.1.zip/jtreg/lib/testng.jar -XX:MaxRAMPercentage=12 -Djava.io.tmpdir=/mesos/work_dir/slaves/4076d11c-c6ed-4d07-84c1-4ab8d55cd975-S149862/frameworks/1735e8a2-a1db-478c-8104-60c8b0af87dd-0196/executors/b205764e-ee1a-4ca9-9215-5fec653c9eac/runs/464ec356-619e-44bf-9247-f85dd796f8af/testoutput/test-support/jtreg_open_test_hotspot_jtreg_serviceability_sa/tmp -Xshare:off -showversion -XX:+CreateCoredumpOnCrash -Xmx512m -XX:MaxMetaspaceSize=64m -XX:+CrashOnOutOfMemoryError TestJmapCore heap ]
[2020-12-16T15:03:11.613843Z] Gathering output for process 46756
[2020-12-16T15:03:12.081754Z] Waiting for completion for process 46756
[2020-12-16T15:03:12.081967Z] Waiting for completion finished for process 46756
Output and diagnostic info for process 46756 was saved into 'pid-46756-output.log'
[2020-12-16T15:03:12.377340Z] Waiting for completion for process 46756
[2020-12-16T15:03:12.378026Z] Waiting for completion finished for process 46756
Run test with ulimit -c: unlimited
[2020-12-16T15:03:12.385781Z] Gathering output for process 46758
[2020-12-16T15:14:16.790198Z] Waiting for completion for process 46758
[2020-12-16T15:14:16.802199Z] Waiting for completion finished for process 46758
Output and diagnostic info for process 46758 was saved into 'pid-46758-output.log'
crashOutputString = [Aborting due to java.lang.OutOfMemoryError: Java heap space
# To suppress the following error report, specify this argument
# after -XX: or in .hotspotrc:  SuppressErrorAt=/debug.cpp:343
#
# A fatal error has been detected by the Java Runtime Environment:
#
#  Internal Error (/System/Volumes/Data/mesos/work_dir/slaves/983c483a-6907-44e0-ad29-98c7183575e2-S18232/frameworks/1735e8a2-a1db-478c-8104-60c8b0af87dd-0196/executors/00183101-76ba-4a20-a54c-72327865748d/runs/4bd3943f-13ee-44e6-beb2-ab2931df253f/workspace/open/src/hotspot/share/utilities/debug.cpp:343), pid=46759, tid=8195
#  fatal error: OutOfMemory encountered: Java heap space
#
# JRE version: Java(TM) SE Runtime Environment (16.0+29) (fastdebug build 16-ea+29-2089)
# Java VM: Java HotSpot(TM) 64-Bit Server VM (fastdebug 16-ea+29-2089, mixed mode, tiered, compressed oops, g1 gc, bsd-amd64)
# Core dump will be written. Default location: core.46759
#
# An error report file with more information is saved as:
# /mesos/work_dir/slaves/4076d11c-c6ed-4d07-84c1-4ab8d55cd975-S149862/frameworks/1735e8a2-a1db-478c-8104-60c8b0af87dd-0196/executors/b205764e-ee1a-4ca9-9215-5fec653c9eac/runs/464ec356-619e-44bf-9247-f85dd796f8af/testoutput/test-support/jtreg_open_test_hotspot_jtreg_serviceability_sa/scratch/1_1/hs_err_pid46759.log
#
# If you would like to submit a bug report, please visit:
#   https://bugreport.java.com/bugreport/crash.jsp
#
]
getCoreFileLocation found stringWithLocation = core.46759
Found core file: core.46759
[2020-12-16T15:14:35.390488Z] Gathering output for process 46894
Attaching to core core.46759 from executable /mesos/work_dir/jib-master/install/jdk-16+29-2089/macosx-x64-debug.jdk/jdk-16/fastdebug/bin/java, please wait...
Debugger attached successfully.
Server compiler detected.
JVM version is 16-ea+29-2089
heap written to heap.hprof

PASSED
----------System.err:(7/210)----------
java version "16-ea" 2021-03-16
Java(TM) SE Runtime Environment (fastdebug build 16-ea+29-2089)
Java HotSpot(TM) 64-Bit Server VM (fastdebug build 16-ea+29-2089, mixed mode)


JavaTest Message: Test complete.

result: Error. Agent error: java.lang.Exception: Agent 9 timed out with a timeout of 960 seconds; check console log for any additional details


Ignore the "fatal error: OutOfMemory encountered: Java heap space"
since that is a normal part of this test.

Since the test shows "PASSED" in System.out, I think the test
managed to pass while the timeout handler was running. The
test is already invoked with "run driver/timeout=240" so with a
default timeoutFactor of 4 the total timeout is 16 minutes/960
seconds.

It could be that this test machine is simply getting to be too old.
Comments
Fix request [17u] I backport this for parity with 17.0.7-oracle. No risk, only a test change. Clean backport. SAP nighlty testing passed.
02-01-2023
A pull request was submitted for review. URL: https://git.openjdk.org/jdk17u-dev/pull/1012 Date: 2022-12-31 18:05:00 +0000
31-12-2022
Changeset: 19ce33d5 Author: Chris Plummer <cjplummer@openjdk.org> Date: 2021-12-02 22:16:55 +0000 URL: https://git.openjdk.java.net/jdk/commit/19ce33d5e770dc3fd7a9588e7954bbb499b7a05c
02-12-2021
Targeting to 18. I don't think we've seen this again, but it's probably worth changing the timeout to 480 just so we can close this out.
30-07-2021
This used to only happen with TestJmapCoreMetaspace. See JDK-8214797. The root cause is sometimes (rarely) core dumps on OSX take an exceedingly long time. Reproducing, even on the same host, is not easy. The solution was doubling the timeout from 240 to 480 (which means 32 minutes instead of 16 minutes with our 4x timefactor). TestJmapCore is different from TestJmapCoreMetaspace in how it forces the core dump, and for some reason core dumps never seemed to take too long with it. We can bump it up to 480 for this test to. BTW, the reason the test says "passed" but then later fails is because jtreg can't force exit the test while its core dumping. So once the timeout happens during the core dump, all jtreg can do is note that it timed out, and then periodically retry forcing it to exit. After the core dump completes, the test gets enough time to finish up before jtreg can try to force it to exit again. However, on exit jtreg notices that the test did time out, so fails it even though the test says it passed.
17-12-2020
I found a similar older bug in my search: JDKJDK-8253811 SA tests time out on macOS 10.13.6 That bug was closed as "External" because the test machine logged in that bug report was determined to be too old and slow.
16-12-2020