JDK-8239878 : Bug in PrintEliminateAllocations code causes TestClhsdbJstackLock.java to fail
  • Type: Bug
  • Component: hotspot
  • Sub-Component: compiler
  • Affected Version: 15
  • Priority: P2
  • Status: Closed
  • Resolution: Fixed
  • OS: linux
  • CPU: x86_64
  • Submitted: 2020-02-24
  • Updated: 2020-07-15
  • Resolved: 2020-02-27
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 b13Fixed
Related Reports
Relates :  
JDK-8238723 - yank_alloc_node must remove membar
Description
The following test failed in the JDK15 CI:

serviceability/sa/TestClhsdbJstackLock.java

Here's a snippet from the failing log:

"Thread-0" #13 prio=5 tid=0x00007fc65c5e2800 nid=0x706b waiting on condition [0x00007fc6209a3000]
   java.lang.Thread.State: TIMED_WAITING (sleeping)
   JavaThread state: _thread_blocked
 - java.lang.Thread.sleep(long) @bci=0 (Interpreted frame)
 - LingeredAppWithLock.lockMethod(java.lang.Object) @bci=7, line=32 (Interpreted frame)
	- locked <0x++++ Eliminated: 1479 Allocate
000000048f454230> ++++ Eliminated: 1321 Allocate
(a java.lang.Class for LingeredAppWithLock)
 - LingeredAppWithLock.lambda$main$0() @bci=2, line=40 (Interpreted frame)
 - LingeredAppWithLock$$Lambda$1.run() @bci=0 (Interpreted frame)
 - java.lang.Thread.run() @bci=11, line=832 (Interpreted frame)

Locked ownable synchronizers:
    - None

<snip>

]
 exitValue = -1

 LingeredApp stdout: [];
 LingeredApp stderr: []
 LingeredApp exitValue = 0
java.lang.RuntimeException: Test ERROR java.lang.RuntimeException: '^\\s+- locked <0x[0-9a-f]+> \\(a java\\.lang\\.Class for LingeredAppWithLock\\)$' missing from stdout/stderr 

	at TestClhsdbJstackLock.main(TestClhsdbJstackLock.java:67)
	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: '^\\s+- locked <0x[0-9a-f]+> \\(a java\\.lang\\.Class for LingeredAppWithLock\\)$' missing from stdout/stderr 

	at jdk.test.lib.process.OutputAnalyzer.shouldMatch(OutputAnalyzer.java:306)
	at ClhsdbLauncher.runCmd(ClhsdbLauncher.java:164)
	at ClhsdbLauncher.run(ClhsdbLauncher.java:216)
	at TestClhsdbJstackLock.main(TestClhsdbJstackLock.java:63)
	... 6 more

JavaTest Message: Test threw exception: java.lang.RuntimeException: Test ERROR java.lang.RuntimeException: '^\\s+- locked <0x[0-9a-f]+> \\(a java\\.lang\\.Class for LingeredAppWithLock\\)$' missing from stdout/stderr 

JavaTest Message: shutting down test

STATUS:Failed.`main' threw exception: java.lang.RuntimeException: Test ERROR java.lang.RuntimeException: '^\\s+- locked <0x[0-9a-f]+> \\(a java\\.lang\\.Class for LingeredAppWithLock\\)$' missing from stdout/stderr
----------rerun:(32/5791)*----------


The search pattern is:

'^\\s+- locked <0x[0-9a-f]+> \\(a java\\.lang\\.Class for LingeredAppWithLock\\)$'

and the output line that should have matched is:

	- locked <0x++++ Eliminated: 1479 Allocate
000000048f454230> ++++ Eliminated: 1321 Allocate
(a java.lang.Class for LingeredAppWithLock)

The "++++ Eliminated: 1479 Allocate" and "++++ Eliminated: 1321 Allocate"
were interleaved in the thread dump output and caused the
pattern match to fail.


Update: Bumping this from P4 -> P2 since this failure mode has now
appeared in a Tier1 CI job set.
Comments
http://cr.openjdk.java.net/~neliasso/8239878/webrev.01/
27-02-2020
URL: https://hg.openjdk.java.net/jdk/jdk/rev/c87cb2daad04 User: neliasso Date: 2020-02-27 12:45:36 +0000
27-02-2020
[~cjplummer] - nice spot! I read that code 3 or 4 times and did not see the bug.. ouch...
26-02-2020
There's a bug in the code: if (PrintEliminateAllocations) { if (alloc->is_AllocateArray()) {} tty->print_cr("++++ Eliminated: %d AllocateArray", alloc->_idx); } else { tty->print_cr("++++ Eliminated: %d Allocate", alloc->_idx); } Note the "{}" at the end of the second line. When formated properly (and adjusting for the errant braces), the reason for the printf becomes obvious: if (PrintEliminateAllocations) { if (alloc->is_AllocateArray()) { } tty->print_cr("++++ Eliminated: %d AllocateArray", alloc->_idx); } else { tty->print_cr("++++ Eliminated: %d Allocate", alloc->_idx); }
26-02-2020
I downloaded the test artifacts and searched for PrintEliminateAllocations in them. There was only one instance, and that was in ClhsdbFlags.jtr, and was the result of requesting all the flags in the target VM. PrintEliminateAllocations was false.
26-02-2020
[~cjplummer] and [~neliasso] - My big question is how the "++++ Eliminated" output is showing up at all. The -XX+PrintEliminateAllocations is false by default and I don't see any signs that it has been set in any of the log file.
26-02-2020
We probably should run this test with -XX:-DoEscapeAnalysis. Possibly also with -XX:+DoEscapeAnalysis and require that it match as it does now, or matches the "++++ Eliminated" output.
25-02-2020
[~neliasso] Can you comment on this? Even without the new "Eliminated" output, I'm not so sure this test would pass as it seems the lock record the test is looking for in the stack trace is indeed eliminated.
25-02-2020
The "++++ Eliminated: NNNN Allocate" output appears to have been added recently by the following fix: JDK-8238723 yank_alloc_node must remove membar However, that output is only supposed to occur with the -XX+PrintEliminateAllocations option set and it is default false.
24-02-2020