JDK-8283354 : serviceability/sa/jmap-hprof/JMapHProfLargeHeapTest.java timed out
  • Type: Bug
  • Component: hotspot
  • Sub-Component: svc-agent
  • Affected Version: 19
  • Priority: P4
  • Status: Closed
  • Resolution: Duplicate
  • OS: os_x_10.15
  • CPU: x86_64
  • Submitted: 2022-03-18
  • Updated: 2022-03-18
  • Resolved: 2022-03-18
Related Reports
Duplicate :  
JDK-8253074 - SA tests time out on macOS after sudo due to runaway coresymbolicationd
Relates :  
JDK-8253074 - SA tests time out on macOS after sudo due to runaway coresymbolicationd
Description
The following test timed out in the JDK19 CI:

serviceability/sa/jmap-hprof/JMapHProfLargeHeapTest.java

Here's a snippet from the log file:

#section:driver
----------messages:(9/392)----------
command: driver JMapHProfLargeHeapTest
reason: User specified action: run driver JMapHProfLargeHeapTest 
Mode: agentvm
Agent id: 11
Additional exports to unnamed modules from @modules: java.base/jdk.internal.misc java.management/sun.management jdk.internal.jvmstat/sun.jvmstat.monitor
Timeout refired 480 times
Timeout information:
--- Timeout information end.
elapsed time (seconds): 803.13
----------configuration:(19/2437)----------

<snip>

----------System.out:(4/2048)----------
STDOUT: /System/Volumes/Data/mesos/work_dir/jib-master/install/jdk-19+15-879/macosx-x64-debug.jdk/jdk-19/fastdebug/bin/java: code object is not signed at all
Target JDK is not signed, therefore not hardened.
Command line: [/System/Volumes/Data/mesos/work_dir/jib-master/install/jdk-19+15-879/macosx-x64-debug.jdk/jdk-19/fastdebug/bin/java -cp /System/Volumes/Data/mesos/work_dir/slaves/c82600aa-2448-475c-8c08-6f02a5b3f3af-S41181/frameworks/1735e8a2-a1db-478c-8104-60c8b0af87dd-0196/executors/33956aad-3a7c-44d1-896b-ea2d39d53019/runs/8770fa24-bb63-451b-a467-985ccffae4ea/testoutput/test-support/jtreg_open_test_hotspot_jtreg_serviceability_sa/classes/3/serviceability/sa/jmap-hprof/JMapHProfLargeHeapTest.d:/System/Volumes/Data/mesos/work_dir/jib-master/install/jdk-19+15-879/src.full/open/test/hotspot/jtreg/serviceability/sa/jmap-hprof:/System/Volumes/Data/mesos/work_dir/slaves/c82600aa-2448-475c-8c08-6f02a5b3f3af-S41181/frameworks/1735e8a2-a1db-478c-8104-60c8b0af87dd-0196/executors/33956aad-3a7c-44d1-896b-ea2d39d53019/runs/8770fa24-bb63-451b-a467-985ccffae4ea/testoutput/test-support/jtreg_open_test_hotspot_jtreg_serviceability_sa/classes/3/test/lib:/System/Volumes/Data/mesos/work_dir/jib-master/install/jtreg/6.1/1/bundles/jtreg-6.1+1.zip/jtreg/lib/javatest.jar:/System/Volumes/Data/mesos/work_dir/jib-master/install/jtreg/6.1/1/bundles/jtreg-6.1+1.zip/jtreg/lib/jtreg.jar:/System/Volumes/Data/mesos/work_dir/jib-master/install/jtreg/6.1/1/bundles/jtreg-6.1+1.zip/jtreg/lib/junit.jar:/System/Volumes/Data/mesos/work_dir/jib-master/install/jtreg/6.1/1/bundles/jtreg-6.1+1.zip/jtreg/lib/hamcrest.jar:/System/Volumes/Data/mesos/work_dir/jib-master/install/jtreg/6.1/1/bundles/jtreg-6.1+1.zip/jtreg/lib/testng.jar:/System/Volumes/Data/mesos/work_dir/jib-master/install/jtreg/6.1/1/bundles/jtreg-6.1+1.zip/jtreg/lib/jcommander.jar:/System/Volumes/Data/mesos/work_dir/jib-master/install/jtreg/6.1/1/bundles/jtreg-6.1+1.zip/jtreg/lib/guice.jar --add-exports=java.management/sun.management=ALL-UNNAMED -Xmx1g JMapHProfLargeHeapProc 22528 ]
Extra
result: Error. Agent error: java.lang.Exception: Agent 11 timed out with a timeout of 480 seconds; check console log for any additional details

This timeout happened in a run with sightings of this bug:

JDK-8253074 SA tests time out on macOS after sudo due to runaway coresymbolicationd

However, there's no sign of a sudo cmd in the logs so I've filed
a new bug.
Comments
As an added note, I think the "sudo" reference in the synopsis of JDK-8253074 is a red herring. It's likely unrelated to the actual issue. You see the "adding sudo" message in the output because it is always printed by any test that needs to do an SA attach, and it's usually the attach that is timing out, not having anything to do with also using sudo. The runaway coresymbolicationd process makes doing the attach extremely slow, so it times out. However the runaway coresymbolicationd process is hogging so much CPU that it can make other processes slow down too, even if not doing anything SA related, and the situation is probably worse if other SA tests are trying to run at the same time and are trying to attach.
18-03-2022
I believe this is being caused by the runaway coresymbolicationd issue, but in this case it is just in general slowing the test down so much that it times out before even getting to the point of launching jhsdb with the sudo command. Here's what the test does before actually starting the jhsdb process with sudo (I've added some comments): --> The following launches the debuggee process. We see this launch command in the output ProcessBuilder procBuilder = ProcessTools.createJavaProcessBuilder( "--add-exports=java.management/sun.management=ALL-UNNAMED", vmArgs, "JMapHProfLargeHeapProc", String.valueOf(heapSize)); procBuilder.redirectError(ProcessBuilder.Redirect.INHERIT); Process largeHeapProc = procBuilder.start(); --> The following scans for the PID of the debuggee in the process output. Note the println() at the end. We see "Extra" in the output, but that's all. try (Scanner largeHeapScanner = new Scanner( largeHeapProc.getInputStream());) { String pidstring = null; if (!largeHeapScanner.hasNext()) { throw new RuntimeException ("Test failed: could not open largeHeapScanner."); } while ((pidstring = largeHeapScanner.findInLine("PID\\[[0-9].*\\]")) == null) { Thread.sleep(500); } int pid = Integer.parseInt(pidstring.substring(4, pidstring.length() - 1)); System.out.println("Extracted pid: " + pid); --> The following prepares for launching the the jhsdb process. SATestUtils.createProcessBuilder() is responsible for adding sudo, and has a println saying as much. We never see this println. We also never see the println at the end if this code block: JDKToolLauncher jMapLauncher = JDKToolLauncher .createUsingTestJDK("jhsdb"); jMapLauncher.addVMArgs(Utils.getTestJavaOpts()); jMapLauncher.addToolArg("jmap"); jMapLauncher.addToolArg("--binaryheap"); jMapLauncher.addToolArg("--pid"); jMapLauncher.addToolArg(String.valueOf(pid)); ProcessBuilder jMapProcessBuilder = SATestUtils.createProcessBuilder(jMapLauncher); System.out.println("jmap command: " + Arrays.toString(jMapLauncher.getCommand())); --> And finally we launch the jhsdb process. We clearly never get this far: Process jMapProcess = jMapProcessBuilder.start(); So nothing SA related is being done in the code that is getting executed, and it's all pretty standard jtreg stuff, yet it is timing out. Admittedly it might be that some of these missing printlns did execute, but are buffered and never flush. I would hope that the timeout would trigger flushing them, but if not then that would also explain the missing sudo cmd in the output.
18-03-2022