JDK-8253028 : SA core file tests still time out on OSX with "java.io.IOException: App waiting timeout"
  • Type: Bug
  • Component: hotspot
  • Sub-Component: svc-agent
  • Affected Version: 16
  • Priority: P3
  • Status: Resolved
  • Resolution: Fixed
  • OS: os_x
  • CPU: x86_64
  • Submitted: 2020-09-10
  • Updated: 2024-11-22
  • Resolved: 2020-09-17
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 16
16 b17Fixed
Related Reports
Relates :  
JDK-8265037 - serviceability/sa/ClhsdbPmap.java#id1 failed with "RuntimeException: Process is still alive. Can't get its output."
Relates :  
JDK-8253602 - SA core file tests still(2) time out on OSX with "java.io.IOException: App waiting timeout"
Relates :  
JDK-8265350 - SA tests time out on macOS 11.0
Description
The following test timed out in the JDK16 CI:

serviceability/sa/ClhsdbPstack.java#id1
serviceability/sa/ClhsdbPmap.java#id1
serviceability/sa/ClhsdbFindPC.java#id3
serviceability/sa/ClhsdbFindPC.java#id1

Here's a snippet from the ClhsdbPstack.java#id1 log file:

#section:main
----------messages:(6/229)----------
command: main ClhsdbPstack true
reason: User specified action: run main/othervm/timeout=240 ClhsdbPstack true 
Mode: othervm [/othervm specified]
Timeout information:
--- Timeout information end.
elapsed time (seconds): 1084.922
----------configuration:(0/0)----------
----------System.out:(10/1877)----------
Starting ClhsdbPstack test: withCore==true
Command line: ['/mesos/work_dir/jib-master/install/jdk-16+16-641/macosx-x64-debug.jdk/jdk-16/fastdebug/bin/java' '-XX:MaxRAMPercentage=12' '-Djava.io.tmpdir=/mesos/work_dir/slaves/4076d11c-c6ed-4d07-84c1-4ab8d55cd975-S106665/frameworks/1735e8a2-a1db-478c-8104-60c8b0af87dd-0196/executors/ab14e180-3147-48f9-b585-acbc7bf5f30f/runs/8f56fe9e-4aec-448a-a1f3-4f047a01b049/testoutput/test-support/jtreg_open_test_hotspot_jtreg_tier1_serviceability/tmp' '-XX:+CreateCoredumpOnCrash' '-Djava.library.path=/mesos/work_dir/jib-master/install/jdk-16+16-641/macosx-x64-debug.test/hotspot/jtreg/native' '-cp' '/mesos/work_dir/slaves/4076d11c-c6ed-4d07-84c1-4ab8d55cd975-S106665/frameworks/1735e8a2-a1db-478c-8104-60c8b0af87dd-0196/executors/ab14e180-3147-48f9-b585-acbc7bf5f30f/runs/8f56fe9e-4aec-448a-a1f3-4f047a01b049/testoutput/test-support/jtreg_open_test_hotspot_jtreg_tier1_serviceability/classes/1/serviceability/sa/ClhsdbPstack_id1.d:/mesos/work_dir/slaves/4076d11c-c6ed-4d07-84c1-4ab8d55cd975-S106665/frameworks/1735e8a2-a1db-478c-8104-60c8b0af87dd-0196/executors/ab14e180-3147-48f9-b585-acbc7bf5f30f/runs/8f56fe9e-4aec-448a-a1f3-4f047a01b049/testoutput/test-support/jtreg_open_test_hotspot_jtreg_tier1_serviceability/classes/1/test/lib' 'jdk.test.lib.apps.LingeredApp' 'dfc81e24-0db3-4dc6-a154-7ec498f5c22f.lck' 'forceCrash']
[2020-09-10T16:35:45.756509Z] Gathering output for process 51330
[2020-09-10T16:35:45.808764Z] Waiting for completion for process 51330
[2020-09-10T16:35:45.808947Z] Waiting for completion finished for process 51330
Output and diagnostic info for process 51330 was saved into 'pid-51330-output.log'
[2020-09-10T16:35:45.857753Z] Waiting for completion for process 51330
[2020-09-10T16:35:45.857905Z] Waiting for completion finished for process 51330
Run test with ulimit -c: unlimited
Timeout refired 960 times
----------System.err:(20/1281)----------
java.lang.RuntimeException: Test ERROR java.io.IOException: App waiting timeout
	at ClhsdbPstack.main(ClhsdbPstack.java:93)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:64)
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.base/java.lang.reflect.Method.invoke(Method.java:564)
	at com.sun.javatest.regtest.agent.MainWrapper$MainThread.run(MainWrapper.java:127)
	at java.base/java.lang.Thread.run(Thread.java:832)
Caused by: java.io.IOException: App waiting timeout
	at jdk.test.lib.apps.LingeredApp.waitAppReady(LingeredApp.java:265)
	at jdk.test.lib.apps.LingeredApp.waitAppReady(LingeredApp.java:295)
	at jdk.test.lib.apps.LingeredApp.startAppExactJvmOpts(LingeredApp.java:417)
	at jdk.test.lib.apps.LingeredApp.startApp(LingeredApp.java:432)
	at ClhsdbPstack.main(ClhsdbPstack.java:63)
	... 6 more

JavaTest Message: Test threw exception: java.lang.RuntimeException: Test ERROR java.io.IOException: App waiting timeout
JavaTest Message: shutting down test

STATUS:Failed.`main' threw exception: java.lang.RuntimeException: Test ERROR java.io.IOException: App waiting timeout
----------rerun:(33/6619)*----------

This issue was previously addressed via:

    JDK-8249150 SA core file tests sometimes time out on OSX with "java.io.IOException: App waiting timeout"

Since this is a Tier1 test failure, this bug would normally
start out as a P2. However, this failure mode tends to be
intermittent so I'm starting it as a P3.
Comments
Changeset: d4269fd5 Author: Chris Plummer <cjplummer@openjdk.org> Date: 2020-09-17 22:17:36 +0000 URL: https://git.openjdk.java.net/jdk/commit/d4269fd5
17-09-2020
Currently waitAppReady() will wait 240 seconds, adjusted by the timeout factor, which is 4x, so that should mean 16 minutes: protected static final int appCoreWaitTime = 240; public void waitAppReady() throws IOException { waitAppReady(forceCrash ? appCoreWaitTime : appWaitTime); } public void waitAppReady(long timeout) throws IOException { // adjust timeout for timeout_factor and convert to ms timeout = Utils.adjustTimeout(timeout) * 1000; long here = epoch(); while (true) { long epoch = epoch(); if (epoch - here > timeout) { throw new IOException("App waiting timeout"); } ... The PStack and PMap tests use a timeout of 240, so the overall timeout for these tests should also be 16 minutes. FindPC uses a timeout of 480, so it should get 32 minutes. Because the PStack and PMap tests have a waitAppReady() timeout that is the same as the test timeout, they get the following error message because the test times out (just a bit) before waitAppReady() times out: Timeout refired 960 times However, the test is not forced to exit until after the core file finishes dumping, which seems to happen after 18 minutes, and once the core file finishes dumping the test is allowed to run long enough to fail in waitAppReady(). FindPC never gets the "Timeout refired 960 times" message, because it's test timeout is 480. So it also just times out in waitAppReady(). We know it can take longer than 16 minutes for a core file to dump, so probably we should bump appCoreWaitTime to 480 (32 minutes after timeout factor is applied) and also bump the timeout for PStack and PMap tests to 480.
14-09-2020