JDK-8251259 : sun/tools/jstatd/TestJstatdRmiPort.java timed out
  • Type: Bug
  • Component: core-svc
  • Sub-Component: tools
  • Affected Version: 16,18,19
  • Priority: P4
  • Status: Open
  • Resolution: Unresolved
  • OS: windows
  • CPU: x86_64
  • Submitted: 2020-08-06
  • Updated: 2022-03-06
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.
Other
tbdUnresolved
Related Reports
Relates :  
JDK-8258802 - ProblemList TestJstatdDefaults.java, TestJstatdRmiPort.java, and TestJstatdServer.java
Description
The following test timed out in the JDK16 CI:

sun/tools/jstatd/TestJstatdRmiPort.java

Here's a snippet from the log file:

#section:main
----------messages:(8/245)----------
command: main TestJstatdRmiPort
reason: User specified action: run main/timeout=60 TestJstatdRmiPort 
Mode: agentvm
Agent id: 28
Timeout refired 600 times
Timeout information:
--- Timeout information end.
elapsed time (seconds): 702.968
----------configuration:(13/1107)*----------
Boot Layer
  class path: C:\\ade\\mesos\\work_dir\\jib-master\\install\\jtreg\\5.1\\b01\\bundles\\jtreg_bin-5.1.zip\\jtreg\\lib\\javatest.jar 
              C:\\ade\\mesos\\work_dir\\jib-master\\install\\jtreg\\5.1\\b01\\bundles\\jtreg_bin-5.1.zip\\jtreg\\lib\\jtreg.jar 
              C:\\ade\\mesos\\work_dir\\jib-master\\install\\jtreg\\5.1\\b01\\bundles\\jtreg_bin-5.1.zip\\jtreg\\lib\\junit.jar 
              C:\\ade\\mesos\\work_dir\\jib-master\\install\\jtreg\\5.1\\b01\\bundles\\jtreg_bin-5.1.zip\\jtreg\\lib\\testng.jar 
  patch:      java.base T:\\testoutput\\test-support\\jtreg_open_test_jdk_svc_tools\\patches\\java.base

Test Layer
  class path: T:\\testoutput\\test-support\\jtreg_open_test_jdk_svc_tools\\classes\\1\\sun\\tools\\jstatd\\TestJstatdRmiPort.d
              C:\\ade\\mesos\\work_dir\\jib-master\\install\\jdk-16+9-362\\src.full\\open\\test\\jdk\\sun\\tools\\jstatd
              T:\\testoutput\\test-support\\jtreg_open_test_jdk_svc_tools\\classes\\1\\test\\lib
              C:\\ade\\mesos\\work_dir\\jib-master\\install\\jdk-16+9-362\\src.full\\open\\test\\lib

----------rerun:(37/4737)*----------

The test specifies "main/timeout=60" but must have been
invoked with a timeoutFactor of 10 since the total timeout
value was 600 seconds/10 minutes. Including the timeout
handle, the test executed for 702.968 second.

I don't see any indicators in the log file as to what went wrong.
Comments
Here's a snippet from the jdk-19+8-409-tier5 sighting: sun/tools/jstatd/TestJstatdRmiPort.java --- ProcessLog --- cmd: /opt/mach5/mesos/work_dir/jib-master/install/jdk-19+8-409/linux-x64-debug.jdk/jdk-19/fastdebug/bin/jstatd -J-XX:+UsePerfData -p 43689 -r 46793 exitvalue: 143 stderr: stdout: [2022-02-01T08:25:39.361695157Z] Waiting for completion for process 927 [2022-02-01T08:25:39.362279726Z] Waiting for completion finished for process 927 Start jstatd: [/opt/mach5/mesos/work_dir/jib-master/install/jdk-19+8-409/linux-x64-debug.jdk/jdk-19/fastdebug/bin/jstatd -J-XX:+UsePerfData -p40583 -r40583] [Jstatd-Thread]:/opt/mach5/mesos/work_dir/jib-master/install/jdk-19+8-409/linux-x64-debug.jdk/jdk-19/fastdebug/bin/jstatd -J-XX:+UsePerfData -p40583 -r40583 [Jstatd-Thread] Could not bind //:40583/JStatRemoteHost to RMI Registry [Jstatd-Thread] java.rmi.NoSuchObjectException: no such object in table [Jstatd-Thread] at java.rmi/sun.rmi.transport.StreamRemoteCall.exceptionReceivedFromServer(StreamRemoteCall.java:304) [Jstatd-Thread] at java.rmi/sun.rmi.transport.StreamRemoteCall.executeCall(StreamRemoteCall.java:280) [Jstatd-Thread] at java.rmi/sun.rmi.server.UnicastRef.invoke(UnicastRef.java:382) [Jstatd-Thread] at java.rmi/sun.rmi.registry.RegistryImpl_Stub.rebind(RegistryImpl_Stub.java:158 result: Error. Agent error: java.lang.Exception: Agent 88 timed out with a timeout of 240 seconds; check console log for any additional details So the test timed out, but it also got a java.rmi.NoSuchObjectException...
01-02-2022
Spotted in the jdk-19+8-409-tier5 CI job set: sun/tools/jstatd/TestJstatdRmiPort.java https://mach5.us.oracle.com/mdash/jobs/mach5-one-jdk-19+8-409-tier5-20220201-0719-28685497/tasks/mach5-one-jdk-19+8-409-tier5-20220201-0719-28685497-tier5-svc-UseNotificationThreadOff-open_test_jdk_jdk_svc-linux-x64-debug-636/results?search=status%3Afailed%20AND%20-state%3Ainvalid https://mach5.us.oracle.com:10060/api/v1/results/mach5-one-jdk-19+8-409-tier5-20220201-0719-28685497-tier5-svc-UseNotificationThreadOff-open_test_jdk_jdk_svc-linux-x64-debug-636-1643704214-1228/log linux-x64-debug: ol7-x64-887134.s4.javaplatfo1iad.oraclevcn.com
01-02-2022
Here's the tail end of the log file from the jdk-18+21-1281-tier5 sighting: Start jstat: [/opt/mach5/mesos/work_dir/jib-master/install/jdk-18+21-1281/linux-x64-debug.jdk/jdk-18/fastdebug/bin/jstat -J-XX:+UsePerfData -J-Duser.language=en -gcutil 12053@ol7-x64-121255 250 5] [2021-10-22T08:16:34.527307091Z] Gathering output for process 12121 [2021-10-22T08:16:36.282757040Z] Waiting for completion for process 12121 [2021-10-22T08:16:36.282894690Z] Waiting for completion finished for process 12121 Output and diagnostic info for process 12121 was saved into 'pid-12121-output.log' S0 S1 E O M CCS YGC YGCT FGC FGCT CGC CGCT GCT 0.00 17.77 0.00 98.97 95.50 82.76 1 0.006 0 0.000 0 0.000 0.006 0.00 17.77 0.00 98.97 95.50 82.76 1 0.006 0 0.000 0 0.000 0.006 0.00 17.77 0.00 98.97 95.50 82.76 1 0.006 0 0.000 0 0.000 0.006 0.00 17.77 0.00 98.97 95.50 82.76 1 0.006 0 0.000 0 0.000 0.006 0.00 17.77 0.00 98.97 95.50 82.76 1 0.006 0 0.000 0 0.000 0.006 [2021-10-22T08:16:36.283654908Z] Waiting for completion for process 12121 [2021-10-22T08:16:36.283744367Z] Waiting for completion finished for process 12121 ProcessThread.stopProcess() will kill process [2021-10-22T08:16:36.692355921Z] Gathering output for process 12053 [2021-10-22T08:16:36.693325114Z] Waiting for completion for process 12053 [2021-10-22T08:16:36.693550240Z] Waiting for completion finished for process 12053 --- ProcessLog --- cmd: /opt/mach5/mesos/work_dir/jib-master/install/jdk-18+21-1281/linux-x64-debug.jdk/jdk-18/fastdebug/bin/jstatd -J-XX:+UsePerfData -J-Djava.security.manager=allow -J-Djava.security.policy=/opt/mach5/mesos/work_dir/jib-master/install/jdk-18+21-1281/src.full/open/test/jdk/sun/tools/jstatd/all.policy -r39787 exitvalue: 143 stderr: stdout: [2021-10-22T08:16:36.693833626Z] Waiting for completion for process 12053 [2021-10-22T08:16:36.693938956Z] Waiting for completion finished for process 12053 Start jstatd: [/opt/mach5/mesos/work_dir/jib-master/install/jdk-18+21-1281/linux-x64-debug.jdk/jdk-18/fastdebug/bin/jstatd -J-XX:+UsePerfData -J-Djava.security.manager=allow -J-Djava ----------System.err:(11/1024)---------- [Jstatd-Thread] WARNING: A terminally deprecated method in java.lang.System has been called [Jstatd-Thread] WARNING: System::setSecurityManager has been called by sun.tools.jstatd.Jstatd (jrt:/jdk.jstatd) [Jstatd-Thread] WARNING: Please consider reporting this to the maintainers of sun.tools.jstatd.Jstatd [Jstatd-Thread] WARNING: System::setSecurityManager will be removed in a future release [Jstatd-Thread] WARNING: A terminally deprecated method in java.lang.System has been called [Jstatd-Thread] WARNING: System::setSecurityManager has been called by sun.tools.jstatd.Jstatd (jrt:/jdk.jstatd) [Jstatd-Thread] WARNING: Please consider reporting this to the maintainers of sun.tools.jstatd.Jstatd [Jstatd-Thread] WARNING: System::setSecurityManager will be removed in a future release [Jstatd-Thread] WARNING: A terminally deprecated method in java.lang.System has been called [Jstatd-Thread] WARNING: System::setSecurityManager has been called by sun.tools.jstatd.Jstatd (jrt:/jdk.jstatd) [Jstatd-Thread] WARNING: Plea result: Error. Agent error: java.lang.Exception: Agent 21 timed out with a timeout of 240 seconds; check console log for any additional details
26-10-2021
JDK-8258802 will be used to ProblemList tests on Win* platforms.
21-12-2020
Here's a snippet from the log file for the jdk-16+27-1884-tier5 sighting: #section:main ----------messages:(8/245)---------- command: main TestJstatdRmiPort reason: User specified action: run main/timeout=60 TestJstatdRmiPort Mode: agentvm Agent id: 25 Timeout refired 240 times Timeout information: --- Timeout information end. elapsed time (seconds): 311.534 ----------configuration:(13/1111)*---------- Boot Layer class path: C:\\ade\\mesos\\work_dir\\jib-master\\install\\jtreg\\5.1\\b01\\bundles\\jtreg_bin-5.1.zip\\jtreg\\lib\\javatest.jar C:\\ade\\mesos\\work_dir\\jib-master\\install\\jtreg\\5.1\\b01\\bundles\\jtreg_bin-5.1.zip\\jtreg\\lib\\jtreg.jar C:\\ade\\mesos\\work_dir\\jib-master\\install\\jtreg\\5.1\\b01\\bundles\\jtreg_bin-5.1.zip\\jtreg\\lib\\junit.jar C:\\ade\\mesos\\work_dir\\jib-master\\install\\jtreg\\5.1\\b01\\bundles\\jtreg_bin-5.1.zip\\jtreg\\lib\\testng.jar patch: java.base T:\\testoutput\\test-support\\jtreg_open_test_jdk_svc_tools\\patches\\java.base Test Layer class path: T:\\testoutput\\test-support\\jtreg_open_test_jdk_svc_tools\\classes\\5\\sun\\tools\\jstatd\\TestJstatdRmiPort.d C:\\ade\\mesos\\work_dir\\jib-master\\install\\jdk-16+27-1884\\src.full\\open\\test\\jdk\\sun\\tools\\jstatd T:\\testoutput\\test-support\\jtreg_open_test_jdk_svc_tools\\classes\\5\\test\\lib C:\\ade\\mesos\\work_dir\\jib-master\\install\\jdk-16+27-1884\\src.full\\open\\test\\lib ----------rerun:(36/4835)*---------- This sighting is more like the original sighting: not a whole lot of info for the timeout failure...
03-12-2020
Here's a snippet from the log file for the jdk-16+27-1887-tier5 sighting: ----------System.out:(61/4222)*---------- Start jstatd: [c:\\ade\\mesos\\work_dir\\jib-master\\install\\jdk-16+27-1887\\windows-x64-debug.jdk\\jdk-16\\fastdebug\\bin\\jstatd.exe -J-XX:+UsePerfData -J-Djava.security.policy=C:\\ade\\mesos\\work_dir\\jib-master\\install\\jdk-16+27-1887\\src.full\\open\\test\\jdk\\sun\\tools\\jstatd\\all.policy -r 1088] [Jstatd-Thread]:c:\\ade\\mesos\\work_dir\\jib-master\\install\\jdk-16+27-1887\\windows-x64-debug.jdk\\jdk-16\\fastdebug\\bin\\jstatd.exe -J-XX:+UsePerfData -J-Djava.security.policy=C:\\ade\\mesos\\work_dir\\jib-master\\install\\jdk-16+27-1887\\src.full\\open\\test\\jdk\\sun\\tools\\jstatd\\all.policy -r 1088 [Jstatd-Thread] jstatd started (bound to /JStatRemoteHost) Jstatd-Thread pid: 474548 Start jps: [c:\\ade\\mesos\\work_dir\\jib-master\\install\\jdk-16+27-1887\\windows-x64-debug.jdk\\jdk-16\\fastdebug\\bin\\jps.exe -J-Xmx512m -J-XX:MaxRAMPercentage=6 -J-Djava.io.tmpdir=t:/testoutput/test-support/jtreg_open_test_jdk_svc_tools/tmp -J-ea -J-esa -J-server -J-XX:+UsePerfData ansible-custom-image-1603380210] [2020-12-03T11:39:07.778675400Z] Gathering output for process 360872 [2020-12-03T11:39:09.403700400Z] Waiting for completion for process 360872 [2020-12-03T11:39:09.403700400Z] Waiting for completion finished for process 360872 Output and diagnostic info for process 360872 was saved into 'pid-360872-output.log' 269732 AgentServer 637640 AgentServer 426660 Main 643596 AgentServer 267848 AgentServer 360872 Jps 147692 AgentServer 429640 Main 11024 AgentServer 474548 Jstatd 333360 AgentServer 367004 AgentServer 68952 jtreg.jar [2020-12-03T11:39:09.412686Z] Waiting for completion for process 360872 [2020-12-03T11:39:09.412686Z] Waiting for completion finished for process 360872 Start jstat: [c:\\ade\\mesos\\work_dir\\jib-master\\install\\jdk-16+27-1887\\windows-x64-debug.jdk\\jdk-16\\fastdebug\\bin\\jstat.exe -J-XX:+UsePerfData -J-Duser.language=en -gcutil 474548@ansible-custom-image-1603380210 250 5] [2020-12-03T11:39:09.428667600Z] Gathering output for process 451088 [2020-12-03T11:39:11.808660900Z] Waiting for completion for process 451088 [2020-12-03T11:39:11.809660600Z] Waiting for completion finished for process 451088 Output and diagnostic info for process 451088 was saved into 'pid-451088-output.log' S0 S1 E O M CCS YGC YGCT FGC FGCT CGC CGCT GCT 0.00 23.04 0.00 0.00 96.10 83.32 1 0.020 0 0.000 0 0.000 0.020 0.00 23.04 0.00 0.00 96.10 83.32 1 0.020 0 0.000 0 0.000 0.020 0.00 23.04 0.00 0.00 96.10 83.32 1 0.020 0 0.000 0 0.000 0.020 0.00 23.04 0.00 0.00 96.10 83.32 1 0.020 0 0.000 0 0.000 0.020 0.00 23.04 0.00 0.00 96.10 83.32 1 0.020 0 0.000 0 0.000 0.020 [2020-12-03T11:39:11.812657400Z] Waiting for completion for process 451088 [2020-12-03T11:39:11.812657400Z] Waiting for completion finished for process 451088 ProcessThread.stopProcess() will kill process [2020-12-03T11:39:11.865654100Z] Gathering output for process 474548 [2020-12-03T11:39:11.867732700Z] Waiting for completion for process 474548 [2020-12-03T11:39:11.868735800Z] Waiting for completion finished for process 474548 --- ProcessLog --- cmd: c:\\ade\\mesos\\work_dir\\jib-master\\install\\jdk-16+27-1887\\windows-x64-debug.jdk\\jdk-16\\fastdebug\\bin\\jstatd.exe -J-XX:+UsePerfData -J-Djava.security.policy=C:\\ade\\mesos\\work_dir\\jib-master\\install\\jdk-16+27-1887\\src.full\\open\\test\\jdk\\sun\\tools\\jstatd\\all.policy -r 1088 exitvalue: 1 stderr: stdout: [2020-12-03T11:39:11.870662500Z] Waiting for completion for process 474548 [2020-12-03T11:39:11.871701100Z] Waiting for completion finished for process 474548 Start jstatd: [c:\\ade\\mesos\\work_dir\\jib-master\\install\\jdk-16+27-1887\\windows-x64-debug.jdk\\jdk-16\\fastdebug\\bin\\jstatd.exe -J-XX:+UsePerfData -J-Djava.security.policy=C:\\ade\\mesos\\work_dir\\jib-master\\install\\jdk-16+27-1887\\src.full\\open\\test\\jdk\\sun\\tools\\jstatd\\all.policy -r1099] [Jstatd-Thread]:c:\\ade\\mesos\\work_dir\\jib-mast result: Error. Agent error: java.lang.Exception: Agent 16 timed out with a timeout of 240 seconds; check console log for any additional details test result: Error. Agent error: java.lang.Exception: Agent 16 timed out with a timeout of 240 seconds; check console log for any additional details
03-12-2020
There is stack trace of the hung process. Here's are some of the more interesting threads: "main" #1 prio=5 os_prio=0 cpu=1578.13ms elapsed=624.37s tid=0x000001c9ac5950e0 nid=0x23d4 in Object.wait() [0x0000002e39ffe000] java.lang.Thread.State: WAITING (on object monitor) Thread: 0x000001c9ac5950e0 [0x23d4] State: _at_safepoint _at_poll_safepoint 0 JavaThread state: _thread_blocked at java.lang.Object.wait(java.base@16-ea/Native Method) - waiting on <0x000001c9cc4226f0> (a java.lang.Thread) at java.lang.Thread.join(java.base@16-ea/Thread.java:1303) - locked <0x000001c9cc4226f0> (a java.lang.Thread) at java.lang.Thread.join(java.base@16-ea/Thread.java:1371) at com.sun.javatest.regtest.agent.MainActionHelper.runClass(MainActionHelper.java:184) at com.sun.javatest.regtest.agent.AgentServer.doMain(AgentServer.java:301) at com.sun.javatest.regtest.agent.AgentServer.run(AgentServer.java:232) at com.sun.javatest.regtest.agent.AgentServer.main(AgentServer.java:69) "AgentVMThread" #23 prio=5 os_prio=0 cpu=296.88ms elapsed=622.80s tid=0x000001c9f200f490 nid=0x3e7c waiting on condition [0x0000002e3b7fd000] java.lang.Thread.State: WAITING (parking) Thread: 0x000001c9f200f490 [0x3e7c] State: _at_safepoint _at_poll_safepoint 0 JavaThread state: _thread_blocked at jdk.internal.misc.Unsafe.park(java.base@16-ea/Native Method) - parking to wait for <0x000001c9cd82eb30> (a java.util.concurrent.CountDownLatch$Sync) at java.util.concurrent.locks.LockSupport.park(java.base@16-ea/LockSupport.java:211) at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(java.base@16-ea/AbstractQueuedSynchronizer.java:714) at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(java.base@16-ea/AbstractQueuedSynchronizer.java:1046) at java.util.concurrent.CountDownLatch.await(java.base@16-ea/CountDownLatch.java:232) at jdk.test.lib.thread.ProcessThread$ProcessRunnable.getProcess(ProcessThread.java:211) at jdk.test.lib.thread.ProcessThread$ProcessRunnable.getPid(ProcessThread.java:200) at jdk.test.lib.thread.ProcessThread.getPid(ProcessThread.java:103) at JstatdTest.waitOnTool(JstatdTest.java:96) at JstatdTest.tryToSetupJstatdProcess(JstatdTest.java:294) at JstatdTest.runTest(JstatdTest.java:348) at JstatdTest.doTest(JstatdTest.java:319) at TestJstatdRmiPort.testRmiPort(TestJstatdRmiPort.java:42) at TestJstatdRmiPort.main(TestJstatdRmiPort.java:35) at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(java.base@16-ea/Native Method) at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(java.base@16-ea/NativeMethodAccessorImpl.java:64) at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(java.base@16-ea/DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(java.base@16-ea/Method.java:564) at com.sun.javatest.regtest.agent.MainActionHelper$AgentVMRunnable.run(MainActionHelper.java:298) at java.lang.Thread.run(java.base@16-ea/Thread.java:832) "Jstatd-Thread" #25 prio=5 os_prio=0 cpu=46.88ms elapsed=621.45s tid=0x000001c9f234fbc0 nid=0x6fe4 waiting on condition [0x0000002e3b8fe000] java.lang.Thread.State: WAITING (parking) Thread: 0x000001c9f234fbc0 [0x6fe4] State: _at_safepoint _at_poll_safepoint 0 JavaThread state: _thread_blocked at jdk.internal.misc.Unsafe.park(java.base@16-ea/Native Method) - parking to wait for <0x000001c9cec09060> (a java.util.concurrent.CountDownLatch$Sync) at java.util.concurrent.locks.LockSupport.park(java.base@16-ea/LockSupport.java:211) at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(java.base@16-ea/AbstractQueuedSynchronizer.java:714) at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(java.base@16-ea/AbstractQueuedSynchronizer.java:1046) at java.util.concurrent.CountDownLatch.await(java.base@16-ea/CountDownLatch.java:232) at jdk.test.lib.process.ProcessTools.startProcess(ProcessTools.java:208) at jdk.test.lib.process.ProcessTools.startProcess(ProcessTools.java:136) at jdk.test.lib.process.ProcessTools.startProcess(ProcessTools.java:257) at jdk.test.lib.thread.ProcessThread$ProcessRunnable.xrun(ProcessThread.java:153) at jdk.test.lib.thread.XRun.run(XRun.java:40) at java.lang.Thread.run(java.base@16-ea/Thread.java:832) at jdk.test.lib.thread.TestThread.run(TestThread.java:123) I think this is the key frame, which we have in two different at jdk.test.lib.process.ProcessTools.startProcess(ProcessTools.java:208) CountDownLatch latch = new CountDownLatch(1); if (linePredicate != null) { StreamPumper.LinePump pump = new StreamPumper.LinePump() { @Override protected void processLine(String line) { if (latch.getCount() > 0 && linePredicate.test(line)) { latch.countDown(); } } }; stdout.addPump(pump); stderr.addPump(pump); } else { latch.countDown(); } final Future<Void> stdoutTask = stdout.process(); final Future<Void> stderrTask = stderr.process(); try { if (timeout > -1) { if (timeout == 0) { latch.await(); <-- ***** line 208 ****** } else { if (!latch.await(Utils.adjustTimeout(timeout), unit)) { throw new TimeoutException(); } } } This thread is part of an attempt to launch jstatd. It was created by "AgentVMThread" with the following ProcessThread jstatdThread = new ProcessThread("Jstatd-Thread", JstatdTest::isJstadReady, getJstatdCmd()); private static boolean isJstadReady(String line) { if (line.contains("Port already in use")) { portInUse = true; return true; } return line.startsWith("jstatd started (bound to "); } So there is a linePredicate string specified, and we are blocked waiting for that string to appear from the jstatd process. With virtually no test output, it's hard to say what actually happened on the jstatd side. There's no core file and no sign that the jstatd process is still running. I'm not sure why startProcess() would remain blocked if the process never launched or if it launched and terminated, but that appears to be the case.
06-08-2020