JDK-8226595 : jvmti/scenarios/contention/TC04/tc04t001/TestDescription.java still fails due to wrong number of MonitorContendedEntered events
  • Type: Bug
  • Component: hotspot
  • Sub-Component: jvmti
  • Affected Version: 13,14
  • Priority: P4
  • Status: Resolved
  • Resolution: Fixed
  • OS: windows
  • CPU: x86_64
  • Submitted: 2019-06-21
  • Updated: 2023-05-31
  • Resolved: 2019-06-22
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 11 JDK 13 JDK 14
11.0.19-oracleFixed 13 b27Fixed 14Fixed
Related Reports
Cloners :  
Duplicate :  
Relates :  
Relates :  
Description
After  JDK-8223736 fix the test still fails:

Spotted in the jdk-13-1364-tier5-20190621 CI job set:

https://java.se.oracle.com:10065/mdash/jobs/mach5-one-jdk-13-1364-tier5-20190621-1308-3306220/results?search=status%3Afailed%20AND%20-state%3Ainvalid

https://java.se.oracle.com:11060/api/v1/results/mach5-one-jdk-13-1364-tier5-20190621-1308-3306220-tier5-rt-JFR-vmTestbase_nsk_jvmti_quick-windows-x64-debug-381-439/log

windows-x64-debug: sca00ico.us.oracle.com 

The most interesting part of the log is:

```
Thread-1: increment event: 194
Thread-0: increment event: 195
Thread-1: increment event: 196
Thread-0: increment event: 197
Thread-1: increment event: 198
Thread-0: increment event: 198 <=== This should not happen as we already had 198 for Thread-1

The following fake exception stacktrace is for failure analysis.
nsk.share.Fake_Exception_for_RULE_Creation: (tc04t001.cpp:267) enterEventsCount == 199
at nsk_lvcomplain(nsk_tools.cpp:172)
# ERROR: tc04t001.cpp, 267: enterEventsCount == 199
# verified assertion is FALSE
# ERROR: tc04t001.cpp, 270: Number of MonitorContendedEnter events: 198
# ERROR: tc04t001.cpp, 275: enteredEventsCount == 199
# verified assertion is FALSE
# ERROR: tc04t001.cpp, 278: Number of MonitorContendedEntered events: 198
``` 

Comments
Fix request [11u] I backport this for parity with 11.0.19-oracle. No risk, only a test change. Clean backport. Test passes. SAP nighlty testing passed.
16-02-2023

A pull request was submitted for review. URL: https://git.openjdk.org/jdk11u-dev/pull/1737 Date: 2023-02-15 08:39:38 +0000
15-02-2023

Git URL: https://github.com/openjdk/jdk/commit/8cf8442085af928c7a601662006bd92eee4a68cb
13-02-2023

URL: http://hg.openjdk.java.net/jdk/jdk13/rev/4d5eabe8d341 User: sspitsyn Date: 2019-06-22 21:36:50 +0000
22-06-2019

The issue is that the lastEnterEventsCount is set in the run() method without a proper sync. So that it can happen that both worker threads Thread-0 and Thread-1 set the same value to the lastEnterEventsCount. Then, the Thread-1 wins a race to enter the increment() method and works correctly. The Thread-0 enters the increment() method with the incorrect lastEnterEventsCount value. The suggested fix is: diff -r a3e3f3caf284 test/hotspot/jtreg/vmTestbase/nsk/jvmti/scenarios/contention/TC04/tc04t001.java --- a/test/hotspot/jtreg/vmTestbase/nsk/jvmti/scenarios/contention/TC04/tc04t001.java Thu Jun 20 23:12:12 2019 -0700 +++ b/test/hotspot/jtreg/vmTestbase/nsk/jvmti/scenarios/contention/TC04/tc04t001.java Fri Jun 21 16:12:48 2019 -0700 @@ -86,23 +86,6 @@ ", expected: " + THREADS_LIMIT*tc04t001Thread.INCREMENT_LIMIT); status = Consts.TEST_FAILED; } - -/* DEBUG -- to check if the threads taking turns in right order - boolean race = false; - for (int i = 1; i < 2*tc04t001Thread.INCREMENT_LIMIT; i++) { - if (tc04t001Thread.passOrder[i] == tc04t001Thread.passOrder[i-1]) { - race = true; - System.out.println("Race condition in the test:"); - System.out.println("passOrder[" + (i-1) + "]:" - + tc04t001Thread.passOrder[i-1]); - System.out.println("passOrder[" + (i) + "]:" - + tc04t001Thread.passOrder[i]); - } - } - if (race) - System.out.println("There was a race condition in the test."); -*/ - return status; } } @@ -117,11 +100,6 @@ static volatile int value = 0; static Flicker flicker = new Flicker(); -/* DEBUG -- to check if the threads taking turns in right order - static volatile int iter = 0; - static volatile int passOrder[] = - new int[INCREMENT_LIMIT*tc04t001.THREADS_LIMIT]; -*/ private int id; private static volatile int lastEnterEventsCount; @@ -135,7 +113,6 @@ public synchronized void run() { for (int i = 0; i < INCREMENT_LIMIT; i++) { flicker.waitFor(id); - lastEnterEventsCount = enterEventsCount(); increment(id); try { wait(1); @@ -145,11 +122,9 @@ } static synchronized void increment(int i) { -/* DEBUG -- to check if the threads taking turns in right order - passOrder[iter++] = i; -*/ flicker.unlock(i); int temp = value; + boolean done = false; // Wait in a loop for a MonitorContendedEnter event. // Timeout is: 20ms * DELAY. @@ -158,17 +133,22 @@ sleep(20); } catch (InterruptedException e) {} + done = (tc04t001.threadsDoneSignal.getCount() == 1); + if (done) { + break; // This thread is the only remaining thread, no more contention + } if (enterEventsCount() > lastEnterEventsCount) { + System.out.println("Thread-" + i + ": increment event: " + enterEventsCount()); break; // Got an expected MonitorContendedEnter event } } - System.out.println("Thread-" + i + ": increment event: " + enterEventsCount()); - if (enterEventsCount() == lastEnterEventsCount) { + if (!done && enterEventsCount() == lastEnterEventsCount) { String msg = "Timeout in waiting for a MonitorContendedEnter event"; throw new RuntimeException(msg); } value = temp + 1; + lastEnterEventsCount = enterEventsCount(); } }
21-06-2019