Bug ID: JDK-8232185 serviceability/sa/ClhsdbJstackXcompStress.java failed due to timeout

JDK-8232185 : serviceability/sa/ClhsdbJstackXcompStress.java failed due to timeout

Type: Bug
Component: hotspot
Sub-Component: svc-agent
Affected Version: 14

Priority: P4
Status: Closed
Resolution: Duplicate
OS: windows
CPU: x86_64

Submitted: 2019-10-11
Updated: 2019-10-15
Resolved: 2019-10-15

Versions (Unresolved/Resolved/Fixed)

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
tbdResolved

Related Reports

Duplicate :

JDK-8231635 - SA Stackwalking code stuck in BasicTypeDataBase.findDynamicTypeForAddress()

Description

The following test timed out in the JDK14 CI:

serviceability/sa/ClhsdbJstackXcompStress.java

Here's a snippet from the log file:

----------System.out:(15/1021)----------
Started LingeredAppWithRecComputation with pid 13740
[2019-10-11T18:54:01.440869200Z] Gathering output for process 2604
DEBUG: [ - LingeredAppWithRecComputation.testLoop() @bci=53, line=54 (Compiled frame; information may be imprecise)]
[2019-10-11T18:54:06.000449500Z] Gathering output for process 8700
[2019-10-11T18:54:09.616513100Z] Gathering output for process 5524
[2019-10-11T18:54:14.081501400Z] Gathering output for process 5928
[2019-10-11T18:54:18.991324600Z] Gathering output for process 17200
[2019-10-11T18:54:23.807781700Z] Gathering output for process 12816
[2019-10-11T18:54:28.325185600Z] Gathering output for process 13792
[2019-10-11T18:54:33.156027900Z] Gathering output for process 2936
[2019-10-11T18:54:37.728169300Z] Gathering output for process 13636
[2019-10-11T18:54:42.452590900Z] Gathering output for process 17748
[2019-10-11T18:54:47.036615200Z] Gathering output for process 5404
[2019-10-11T18:54:51.405218600Z] Gathering output for process 13464
Timeout refired 480 times
----------System.err:(4/860)*----------
java version "14-ea" 2020-03-17
Java(TM) SE Runtime Environment (fastdebug build 14-ea+19-796)
Java HotSpot(TM) 64-Bit Server VM (fastdebug build 14-ea+19-796, mixed mode)
Command line: ['c:\\ade\\mesos\\work_dir\\jib-master\\install\\jdk-14+19-796\\windows-x64-debug.jdk\\jdk-14\\fastdebug/bin/java' '-Xcomp' '-XX:CompileCommand=dontinline,LingeredAppWithRecComputation.factorial' '-XX:CompileCommand=compileonly,LingeredAppWithRecComputation.testLoop' '-XX:CompileCommand=compileonly,LingeredAppWithRecComputation.factorial' '-cp' 'T:\\testoutput\\test-support\\jtreg_open_test_hotspot_jtreg_tier1_serviceability\\classes\\5\\serviceability\\sa\\ClhsdbJstackXcompStress.d;T:\\testoutput\\test-support\\jtreg_open_test_hotspot_jtreg_tier1_serviceability\\classes\\5\\test\\lib' 'LingeredAppWithRecComputation' 'e611a8f7-f2b4-4e5d-ae47-14c87a6e97dc.lck' ]
----------rerun:(37/4995)*----------

Comments

OK, I see. Thanks for the clarification.
15-10-2019
I should clarify. I meant the same from the sun.jvm.hotspot.runtime.JavaThread.getLastJavaVFrameDbg frame on up to the frame where it hangs. at sun.jvm.hotspot.types.basic.BasicTypeDataBase.findDynamicTypeForAddress(jdk.hotspot.agent@14-ea/BasicTypeDataBase.java:328) at sun.jvm.hotspot.runtime.VirtualBaseConstructor.instantiateWrapperFor(jdk.hotspot.agent@14-ea/VirtualBaseConstructor.java:102) at sun.jvm.hotspot.utilities.GrowableArray.at(jdk.hotspot.agent@14-ea/GrowableArray.java:61) at sun.jvm.hotspot.code.CodeCache.findBlobUnsafe(jdk.hotspot.agent@14-ea/CodeCache.java:102) at sun.jvm.hotspot.code.CodeCache.findBlob(jdk.hotspot.agent@14-ea/CodeCache.java:85) at sun.jvm.hotspot.runtime.x86.X86Frame.adjustForDeopt(jdk.hotspot.agent@14-ea/X86Frame.java:106) at sun.jvm.hotspot.runtime.x86.X86Frame.initFrame(jdk.hotspot.agent@14-ea/X86Frame.java:138) at sun.jvm.hotspot.runtime.x86.X86Frame.<init>(jdk.hotspot.agent@14-ea/X86Frame.java:143) at sun.jvm.hotspot.runtime.x86.X86Frame.senderForCompiledFrame(jdk.hotspot.agent@14-ea/X86Frame.java:408) at sun.jvm.hotspot.runtime.x86.X86Frame.sender(jdk.hotspot.agent@14-ea/X86Frame.java:290) at sun.jvm.hotspot.runtime.Frame.sender(jdk.hotspot.agent@14-ea/Frame.java:205) at sun.jvm.hotspot.runtime.amd64.AMD64CurrentFrameGuess.run(jdk.hotspot.agent@14-ea/AMD64CurrentFrameGuess.java:140) at sun.jvm.hotspot.runtime.win32_amd64.Win32AMD64JavaThreadPDAccess.getCurrentFrameGuess(jdk.hotspot.agent@14-ea/Win32AMD64JavaThreadPDAccess.java:103) at sun.jvm.hotspot.runtime.JavaThread.getCurrentFrameGuess(jdk.hotspot.agent@14-ea/JavaThread.java:265) at sun.jvm.hotspot.runtime.JavaThread.getLastJavaVFrameDbg(jdk.hotspot.agent@14-ea/JavaThread.java:227) at sun.jvm.hotspot.tools.StackTrace.run(jdk.hotspot.agent@14-ea/StackTrace.java:81) at sun.jvm.hotspot.tools.StackTrace.run(jdk.hotspot.agent@14-ea/StackTrace.java:45) at sun.jvm.hotspot.tools.JStack.run(jdk.hotspot.agent@14-ea/JStack.java:67) at sun.jvm.hotspot.tools.Tool.startInternal(jdk.hotspot.agent@14-ea/Tool.java:262) at sun.jvm.hotspot.tools.Tool.start(jdk.hotspot.agent@14-ea/Tool.java:225) at sun.jvm.hotspot.tools.Tool.execute(jdk.hotspot.agent@14-ea/Tool.java:118) at sun.jvm.hotspot.tools.JStack.runWithArgs(jdk.hotspot.agent@14-ea/JStack.java:90) at sun.jvm.hotspot.SALauncher.runJSTACK(jdk.hotspot.agent@14-ea/SALauncher.java:290) at sun.jvm.hotspot.SALauncher$$Lambda$3/0x0000000800bf1840.accept(jdk.hotspot.agent@14-ea/Unknown Source) at sun.jvm.hotspot.SALauncher.main(jdk.hotspot.agent@14-ea/SALauncher.java:406)
15-10-2019
Hmm, seeing the same stack trace for process 13464 as in JDK-8231635 doesn't make any sense. jmap cannot show up in the stack trace for LingeredAppWithRecComputation as host app for "jhsdb jstack". Two possibilities come to mind: 1) serviceability/sa/ClhsdbJstackXcompStress.java sees processes started by other tests. Which somehow trigger the lockup 2) Some other test tries to perform "jhsdb jmap" on a process started by this test. My guess would be on 2)
15-10-2019
This is a newer test that was added for JDK-8196969. However, this failure is due to JDK-8231635, a pre-existing bug. See analysis below. We will probably need to problemlist this test since it is failing once or twice a day in our nightly testing, although for some reason only on windows-x64 so far In the log you will see: ----------System.out:(15/1021)---------- Started LingeredAppWithRecComputation with pid 13740 [2019-10-11T18:54:01.440869200Z] Gathering output for process 2604 DEBUG: [ - LingeredAppWithRecComputation.testLoop() @bci=53, line=54 (Compiled frame; information may be imprecise)] [2019-10-11T18:54:06.000449500Z] Gathering output for process 8700 [2019-10-11T18:54:09.616513100Z] Gathering output for process 5524 [2019-10-11T18:54:14.081501400Z] Gathering output for process 5928 [2019-10-11T18:54:18.991324600Z] Gathering output for process 17200 [2019-10-11T18:54:23.807781700Z] Gathering output for process 12816 [2019-10-11T18:54:28.325185600Z] Gathering output for process 13792 [2019-10-11T18:54:33.156027900Z] Gathering output for process 2936 [2019-10-11T18:54:37.728169300Z] Gathering output for process 13636 [2019-10-11T18:54:42.452590900Z] Gathering output for process 17748 [2019-10-11T18:54:47.036615200Z] Gathering output for process 5404 [2019-10-11T18:54:51.405218600Z] Gathering output for process 13464 Timeout refired 480 times If you look at the process 13464 in processes.html, you will see the same stack trace as shown in JDK-8231635.
15-10-2019
Almost 11 minutes is definitely a outlier for other runs for this test in the JDK14 CI. This timeout was on an OCI machine so it's not what I would call a wimpy machine.
11-10-2019