JDK-8242168 : ClhsdbFindPC.java failed due to "RuntimeException: 'In code in NMethod for LingeredAppWithTrivialMain.main' missing from stdout/stderr"
  • Type: Bug
  • Component: hotspot
  • Sub-Component: svc-agent
  • Affected Version: 15
  • Priority: P4
  • Status: Resolved
  • Resolution: Fixed
  • OS: windows
  • CPU: x86_64
  • Submitted: 2020-04-05
  • Updated: 2022-02-19
  • Resolved: 2020-04-07
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 15
15 b18Fixed
Related Reports
Relates :  
JDK-8281614 - serviceability/sa/ClhsdbFindPC.java fails with java.lang.RuntimeException: 'In code in NMethod for jdk/test/lib/apps/LingeredApp.steadyState' missing from stdout/stderr
Relates :  
JDK-8240698 - LingeredApp does not pass getTestJavaOpts() to the children process if vmArguments is already specified
Description
The following test failed in the JDK15 CI:

serviceability/sa/ClhsdbFindPC.java#id0

Here's a snippet from the log file:

----------System.err:(37/2719)*----------
Command line: ['c:\\ade\\mesos\\work_dir\\jib-master\\install\\jdk-15+18-721\\windows-x64-debug.jdk\\jdk-15\\fastdebug/bin/java' '-XX:MaxRAMPercentage=3' '-Xcomp' '-XX:+CreateCoredumpOnCrash' '-ea' '-esa' '-XX:CompileThreshold=100' '-XX:+UnlockExperimentalVMOptions' '-server' '-XX:+TieredCompilation' '-XX:+DeoptimizeALot' '-Xcomp' '-cp' 'T:\\testoutput\\test-support\\jtreg_open_test_hotspot_jtreg_hotspot_serviceability\\classes\\5\\serviceability\\sa\\ClhsdbFindPC_id0.d;T:\\testoutput\\test-support\\jtreg_open_test_hotspot_jtreg_hotspot_serviceability\\classes\\5\\test\\lib' 'LingeredAppWithTrivialMain' '0a559906-6ed9-44ef-9648-75bb2ce7c7f2.lck' ]
 stdout: [ + findpc 0x000000678864a3b3
Address 0x000000678864a3b3: In interpreter codelet "invoke return entry points"
invoke return entry points [0x0000006788649a70, 0x000000678864a4a0)  2608 bytes  
];
 stderr: [ + findpc 0x000000678864a3b3
Address 0x000000678864a3b3: In interpreter codelet "invoke return entry points"
invoke return entry points [0x0000006788649a70, 0x000000678864a4a0)  2608 bytes  
]
 exitValue = -1

 LingeredApp stdout: [];
 LingeredApp stderr: []
 LingeredApp exitValue = 0
java.lang.RuntimeException: Test ERROR java.lang.RuntimeException: 'In code in NMethod for LingeredAppWithTrivialMain.main' missing from stdout/stderr 

	at ClhsdbFindPC.testFindPC(ClhsdbFindPC.java:111)
	at ClhsdbFindPC.main(ClhsdbFindPC.java:120)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	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.lang.RuntimeException: 'In code in NMethod for LingeredAppWithTrivialMain.main' missing from stdout/stderr 

	at jdk.test.lib.process.OutputAnalyzer.shouldMatch(OutputAnalyzer.java:306)
	at ClhsdbLauncher.runCmd(ClhsdbLauncher.java:163)
	at ClhsdbLauncher.run(ClhsdbLauncher.java:200)
	at ClhsdbFindPC.testFindPC(ClhsdbFindPC.java:107)
	... 7 more

JavaTest Message: Test threw exception: java.lang.RuntimeException: Test ERROR java.lang.RuntimeException: 'In code in NMethod for LingeredAppWithTrivialMain.main' missing from stdout/stderr 

JavaTest Message: shutting down test

STATUS:Failed.`main' threw exception: java.lang.RuntimeException: Test ERROR java.lang.RuntimeException: 'In code in NMethod for LingeredAppWithTrivialMain.main' missing from stdout/stderr
----------rerun:(47/5491)*----------
Comments
URL: https://hg.openjdk.java.net/jdk/jdk/rev/51e69a59238f User: cjplummer Date: 2020-04-07 16:38:20 +0000
07-04-2020
The startAppExactJvmOpts() means that these test will ignore Graal, C1 (setting by tiered level) and any other modes. I think it is better to disable execution with DeoptimizeALot for any tests where compiled frames are expected.
06-04-2020
ClhsdbJstackXcompStress.java also seems vulnerable since it uses startApp() and searches for "Compiled frame". However, it just needs for at least one frame to be compiled in order to pass, and is seems even with DeoptimizeALot this still happens. I'm starting to second guess if both of these tests maybe should just use startAppExactJvmOpts() rather than disabling when using -XX:+DeoptimizeALot. I'll wait to see what [~lmesnik] thinks before doing anything.
05-04-2020
The test is failing in this manner on about 15% of the runs. There reason we are suddenly seeing it is due to JDK-8240698. The test contains the following: LingeredApp.startApp(theApp, "-Xcomp"); startApp() was modified to prepend the test.vm.opts, and now you need to use startAppExactJvmOpts() if you don't want this behavior. I looked at older passing runs and they do not include all the test.vm.opts when running LingeredApp. For this test it was decided to "fix" it by allowing the prepending to happen. That probably was still the right choice, but now we need to address the failures due to DeoptimizeALot, so that still suggests fixing with @requires rather than not pre-pending the test.vm.opts.
05-04-2020
I see a lot of tests have the following: * @requires vm.opt.DeoptimizeALot != true This test clearly needs it also. I'll add it.
05-04-2020
This seems to be a test incompatibility with -XX:+DeoptimizeALot. From the failing log: "main" #1 prio=5 tid=0x00000067f1086000 nid=0x88f4 waiting on condition [0x00000067f082f000] java.lang.Thread.State: TIMED_WAITING (sleeping) JavaThread state: _thread_blocked - java.lang.Thread.sleep(long) @bci=0, pc=0x00000067902fde79, Method*=0x00000008000f7c48 (Compiled frame; information may be imprecise) - jdk.test.lib.apps.LingeredApp.main(java.lang.String[]) @bci=54, line=499, pc=0x000000678864a3b3, Method*=0x0000006799c43cf8 (Interpreted frame) - LingeredAppWithTrivialMain.main(java.lang.String[]) @bci=1, line=33, pc=0x000000678864a3b3, Method*=0x0000006799c40268 (Interpreted frame) hsdb> + findpc 0x000000678864a3b3 Address 0x000000678864a3b3: In interpreter codelet "invoke return entry points" invoke return entry points [0x0000006788649a70, 0x000000678864a4a0) 2608 bytes From a passing log: "main" #1 prio=5 tid=0x000000aa55a66000 nid=0x4e1c waiting on condition [0x000000aa551df000] java.lang.Thread.State: TIMED_WAITING (sleeping) JavaThread state: _thread_blocked - java.lang.Thread.sleep(long) @bci=0, pc=0x000000aa65ddccf9, Method*=0x000000aa000f88e8 (Compiled frame; information may be imprecise) - jdk.test.lib.apps.LingeredApp.main(java.lang.String[]) @bci=54, line=499, pc=0x000000aa5ebf5ad4, Method*=0x000000aa40fa3cf8 (Compiled frame) - LingeredAppWithTrivialMain.main(java.lang.String[]) @bci=1, line=33, pc=0x000000aa5ebf5284, Method*=0x000000aa40fa0268 (Compiled frame) hsdb> + findpc 0x000000aa5ebf5284 Address 0x000000aa5ebf5284: In code in NMethod for LingeredAppWithTrivialMain.main([Ljava/lang/String;)V content: [0x000000aa5ebf5240, 0x000000aa5ebf5370), code: [0x000000aa5ebf5240, 0x000000aa5ebf5370), data: [0x000000aa5ebf5370, 0x000000aa5ebf53f8), oops: [0x000000aa5ebf5370, 0x000000aa5ebf5378), frame size: 64 Notice that findpc is called using the pc from the LingeredAppWithTrivialMain.main frame. It's expecting the frame to be compiled, but it is not. The test has both -Xcomp and -Xint modes: if (withXcomp) { expStrMap.put(cmdStr, List.of( "In code in NMethod for LingeredAppWithTrivialMain.main", "content:", "oops:", "frame size:")); } else { expStrMap.put(cmdStr, List.of( "In interpreter codelet")); } So the error indicates it is running in -Xcomp mode. The log supports this: Started LingeredApp (-Xcomp) with pid 12536 And: Command line: ['c:\\ade\\mesos\\work_dir\\jib-master\\install\\jdk-15+18-721\\windows-x64-debug.jdk\\jdk-15\\fastdebug/bin/java' '-XX:MaxRAMPercentage=3' '-Xcomp' '-XX:+CreateCoredumpOnCrash' '-ea' '-esa' '-XX:CompileThreshold=100' '-XX:+UnlockExperimentalVMOptions' '-server' '-XX:+TieredCompilation' '-XX:+DeoptimizeALot' '-Xcomp' '-cp' 'T:\\testoutput\\test-support\\jtreg_open_test_hotspot_jtreg_hotspot_serviceability\\classes\\5\\serviceability\\sa\\ClhsdbFindPC_id0.d;T:\\testoutput\\test-support\\jtreg_open_test_hotspot_jtreg_hotspot_serviceability\\classes\\5\\test\\lib' 'LingeredAppWithTrivialMain' '0a559906-6ed9-44ef-9648-75bb2ce7c7f2.lck' ] But notice it is also being run with -XX:+DeoptimizeALot and most of the methods are not compiled, and some say they've been decompiled. For example: - java.lang.ref.ReferenceQueue.remove(long) @bci=59, line=155, pc=0x0000006789119c34, Method*=0x000000080036d0d0 (Compiled frame [deoptimized]) - locked <0x00000000c5028c60> (a java.lang.ref.ReferenceQueue$Lock) So I'd say this test is incompatible with -XX:+DeoptimizeALot and should not be run with it. I'm not sure why this hasn't popped up before. This test was just restructured a bit by JDK-8240698. However, I don't see any changes in that webrev that would impact allowing -XX:+DeoptimizeALot. I think maybe we've just gotten lucky in the past. It is a tier7 run, so we don't run the test in this manner that often.
05-04-2020