JDK-8224555 : vmTestbase/nsk/jvmti/scenarios/contention/TC02/tc02t001/TestDescription.java failed
  • Type: Bug
  • Component: hotspot
  • Sub-Component: jvmti
  • Affected Version: 11,13
  • Priority: P3
  • Status: Resolved
  • Resolution: Fixed
  • Submitted: 2019-05-21
  • Updated: 2020-09-22
  • 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.10-oracleFixed 13 b27Fixed 14Fixed
Related Reports
Relates :  
JDK-8201603 - MonitorContendedEnter failure in nsk/jvmti/scenarios/contention/TC02/tc02t001
Relates :  
JDK-8223736 - jvmti/scenarios/contention/TC04/tc04t001/TestDescription.java fails due to wrong number of MonitorContendedEntered events
Relates :  
JDK-8217348 - assert(thread->is_Java_thread()) failed: just checking
Description
vmTestbase/nsk/jvmti/scenarios/contention/TC02/tc02t001/TestDescription.java	

Use jcmd 44100 JFR.dump name=1 filename=FILEPATH to copy recording data to file.
The following fake exception stacktrace is for failure analysis. 
nsk.share.Fake_Exception_for_RULE_Creation: (tc02t001.cpp:126) line == lines[enterEventsCount] || line == (lines[enterEventsCount] + 1)
	at nsk_lvcomplain(nsk_tools.cpp:172)
# ERROR: tc02t001.cpp, 126: line == lines[enterEventsCount] || line == (lines[enterEventsCount] + 1)
#   verified assertion is FALSE
# ERROR: tc02t001.cpp, 129: MonitorContendedEnter event: thread=0000002C997169D8, object=0000002C997169E0, line=133
# ERROR: tc02t001.cpp, 171: line == lines[enteredEventsCount] || line == (lines[enteredEventsCount] + 1)
#   verified assertion is FALSE
# ERROR: tc02t001.cpp, 174: MonitorContendedEntered event: thread=0000002C997169D8, object=0000002C997169E0, line=133
# ERROR: tc02t001.cpp, 126: line == lines[enterEventsCount] || line == (lines[enterEventsCount] + 1)
#   verified assertion is FALSE
# ERROR: tc02t001.cpp, 129: MonitorContendedEnter event: thread=0000002C997169D8, object=0000002C997169E0, line=138
# ERROR: tc02t001.cpp, 171: line == lines[enteredEventsCount] || line == (lines[enteredEventsCount] + 1)
#   verified assertion is FALSE
# ERROR: tc02t001.cpp, 174: MonitorContendedEntered event: thread=0000002C997169D8, object=0000002C997169E0, line=138
# ERROR: tc02t001.cpp, 301: enterEventsCount == 3
#   verified assertion is FALSE
# ERROR: tc02t001.cpp, 308: enteredEventsCount == 3
#   verified assertion is FALSE
Comments
Fix request (11u) I would like to downport this for parity with 11.0.10-oracle. I had to resolve as the file is C in 11 and C++ in the original. Also, the removed code uses longer sleep() times in the original which made the chunk deleting it not apply. http://mail.openjdk.java.net/pipermail/jdk-updates-dev/2020-September/003844.html
22-09-2020
This issue is similar to the bug JDK-8223736. The suggested fix is: diff -r 79a7fc6c9bc7 test/hotspot/jtreg/vmTestbase/nsk/jvmti/scenarios/contention/TC02/tc02t001.java --- a/test/hotspot/jtreg/vmTestbase/nsk/jvmti/scenarios/contention/TC02/tc02t001.java Thu Jun 20 18:29:34 2019 -0400 +++ b/test/hotspot/jtreg/vmTestbase/nsk/jvmti/scenarios/contention/TC02/tc02t001.java Thu Jun 20 21:26:42 2019 -0700 @@ -1,5 +1,5 @@ /* - * Copyright (c) 2004, 2018, Oracle and/or its affiliates. All rights reserved. + * Copyright (c) 2004, 2019, Oracle and/or its affiliates. All rights reserved. * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER. * * This code is free software; you can redistribute it and/or modify it @@ -28,86 +28,7 @@ import nsk.share.*; import nsk.share.jvmti.*; -// THIS TEST IS LINE NUMBER SENSITIVE - -public class tc02t001 extends DebugeeClass { - - // run test from command line - public static void main(String argv[]) { - argv = nsk.share.jvmti.JVMTITest.commonInit(argv); - - // JCK-compatible exit - System.exit(run(argv, System.out) + Consts.JCK_STATUS_BASE); - } - - // run test from JCK-compatible environment - public static int run(String argv[], PrintStream out) { - return new tc02t001().runIt(argv, out); - } - - /* =================================================================== */ - - // scaffold objects - ArgumentHandler argHandler = null; - Log log = null; - int status = Consts.TEST_PASSED; - static long timeout = 0; - - // tested thread - tc02t001Thread thread = null; - - // run debuggee - public int runIt(String argv[], PrintStream out) { - argHandler = new ArgumentHandler(argv); - log = new Log(out, argHandler); - timeout = argHandler.getWaitTime() * 60 * 1000; - log.display("Timeout = " + timeout + " msc."); - - thread = new tc02t001Thread("Debuggee Thread"); - synchronized (thread.M) { - thread.start(); - thread.startingBarrier.waitFor(); - status = checkStatus(status); - - thread.waitingBarrier1.unlock(); - try { - Thread.sleep(1000); // Wait for contended "synchronized (M)" - thread.M.wait(timeout); - } catch (InterruptedException e) { - throw new Failure(e); - } - - thread.waitingBarrier2.unlock(); - try { - Thread.sleep(1000); // Wait for contended "synchronized (M)" - thread.M.wait(timeout); - } catch (InterruptedException e) { - throw new Failure(e); - } - - thread.waitingBarrier3.unlock(); - try { - Thread.sleep(1000); // Wait for contended "synchronized (M)" - thread.M.wait(timeout); - } catch (InterruptedException e) { - throw new Failure(e); - } - } - - try { - thread.join(timeout); - } catch (InterruptedException e) { - throw new Failure(e); - } - - log.display("Debugee finished"); - status = checkStatus(status); - - return status; - } -} - -/* =================================================================== */ +// THIS CLASS IS LINE NUMBER SENSITIVE class tc02t001Thread extends Thread { public Wicket startingBarrier = new Wicket(); @@ -139,3 +60,97 @@ } } } + +/* =================================================================== */ + +public class tc02t001 extends DebugeeClass { + + // run test from command line + public static void main(String argv[]) { + argv = nsk.share.jvmti.JVMTITest.commonInit(argv); + + // JCK-compatible exit + System.exit(run(argv, System.out) + Consts.JCK_STATUS_BASE); + } + + // run test from JCK-compatible environment + public static int run(String argv[], PrintStream out) { + return new tc02t001().runIt(argv, out); + } + + /* =================================================================== */ + + // scaffold objects + ArgumentHandler argHandler = null; + Log log = null; + int status = Consts.TEST_PASSED; + static long timeout = 0; + + private static volatile int lastEnterEventsCount; + private static native int enterEventsCount(); + + // tested thread + tc02t001Thread thread = null; + + static void log (String msg) { System.out.println(msg); } + + private void waitForContendedEnterEvent() { + try { + for (int j = 0; j < 1000; j++) { + Thread.sleep(20); + if (enterEventsCount() > lastEnterEventsCount) { + log("Got expected MonitorContendedEnter event\n"); + break; + } + } + if (enterEventsCount() == lastEnterEventsCount) { + String msg = "Timeout in waiting for a MonitorContendedEnter event"; + throw new RuntimeException(msg); + } + thread.M.wait(timeout); + } catch (InterruptedException e) { + throw new Failure(e); + } + } + + // run debuggee + public int runIt(String argv[], PrintStream out) { + argHandler = new ArgumentHandler(argv); + log = new Log(out, argHandler); + timeout = argHandler.getWaitTime() * 60 * 1000; + log.display("Timeout = " + timeout + " msc."); + + thread = new tc02t001Thread("Debuggee Thread"); + synchronized (thread.M) { + thread.start(); + thread.startingBarrier.waitFor(); + status = checkStatus(status); + + lastEnterEventsCount = enterEventsCount(); + thread.waitingBarrier1.unlock(); + log("Waiting for MonitorEnterEvent #1"); + waitForContendedEnterEvent(); + + lastEnterEventsCount = enterEventsCount(); + thread.waitingBarrier2.unlock(); + log("Waiting for MonitorEnterEvent #2"); + waitForContendedEnterEvent(); + + lastEnterEventsCount = enterEventsCount(); + thread.waitingBarrier3.unlock(); + log("Waiting for MonitorEnterEvent #3"); + waitForContendedEnterEvent(); + } + + try { + thread.join(timeout); + } catch (InterruptedException e) { + throw new Failure(e); + } + + log.display("Debugee finished"); + status = checkStatus(status); + + return status; + } +} diff -r 79a7fc6c9bc7 test/hotspot/jtreg/vmTestbase/nsk/jvmti/scenarios/contention/TC02/tc02t001/tc02t001.cpp --- a/test/hotspot/jtreg/vmTestbase/nsk/jvmti/scenarios/contention/TC02/tc02t001/tc02t001.cpp Thu Jun 20 18:29:34 2019 -0400 +++ b/test/hotspot/jtreg/vmTestbase/nsk/jvmti/scenarios/contention/TC02/tc02t001/tc02t001.cpp Thu Jun 20 21:26:42 2019 -0700 @@ -1,5 +1,5 @@ /* - * Copyright (c) 2004, 2018, Oracle and/or its affiliates. All rights reserved. + * Copyright (c) 2004, 2019, Oracle and/or its affiliates. All rights reserved. * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER. * * This code is free software; you can redistribute it and/or modify it @@ -38,7 +38,7 @@ static jthread thread = NULL; static jobject object_M = NULL; /* line numbers of "synchronized (M)" clauses in java part of the test */ -static jint lines[] = { 127, 132, 137 }; +static jint lines[] = { 48, 53, 58 }; static volatile int enterEventsCount = 0; static volatile int enteredEventsCount = 0; @@ -370,6 +370,11 @@ return JNI_OK; } +JNIEXPORT jint JNICALL +Java_nsk_jvmti_scenarios_contention_TC02_tc02t001_enterEventsCount(JNIEnv* jni, jclass klass) { + return enterEventsCount; +} + /* ========================================================================== */ }
21-06-2019
I've commented out the sleep(1000) as in the fragment below: thread.waitingBarrier1.unlock(); try { // Thread.sleep(1000); // Wait for contended "synchronized (M)" thread.M.wait(timeout); } catch (InterruptedException e) { throw new Failure(e); } And got it reproduced: Use jcmd 43451 JFR.dump name=1 filename=FILEPATH to copy recording data to file. The following fake exception stacktrace is for failure analysis. nsk.share.Fake_Exception_for_RULE_Creation: (tc02t001.cpp:126) line == lines[enterEventsCount] || line == (lines[enterEventsCount] + 1) at nsk_lvcomplain(nsk_tools.cpp:172) # ERROR: tc02t001.cpp, 126: line == lines[enterEventsCount] || line == (lines[enterEventsCount] + 1) # verified assertion is FALSE # ERROR: tc02t001.cpp, 129: MonitorContendedEnter event: thread=0x7f160c0015a0, object=0x7f160c0015a8, line=133 # ERROR: tc02t001.cpp, 171: line == lines[enteredEventsCount] || line == (lines[enteredEventsCount] + 1) # verified assertion is FALSE # ERROR: tc02t001.cpp, 174: MonitorContendedEntered event: thread=0x7f160c0015a0, object=0x7f160c0015a8, line=133 # ERROR: tc02t001.cpp, 126: line == lines[enterEventsCount] || line == (lines[enterEventsCount] + 1) # verified assertion is FALSE # ERROR: tc02t001.cpp, 129: MonitorContendedEnter event: thread=0x7f160c0015a0, object=0x7f160c0015a8, line=138 # ERROR: tc02t001.cpp, 171: line == lines[enteredEventsCount] || line == (lines[enteredEventsCount] + 1) # verified assertion is FALSE # ERROR: tc02t001.cpp, 174: MonitorContendedEntered event: thread=0x7f160c0015a0, object=0x7f160c0015a8, line=138 # ERROR: tc02t001.cpp, 301: enterEventsCount == 3 # verified assertion is FALSE # ERROR: tc02t001.cpp, 308: enteredEventsCount == 3 # verified assertion is FALSE
20-06-2019
The conclusion in my comment above seems to be right. The last two errors are: # ERROR: tc02t001.cpp, 301: enterEventsCount == 3 # verified assertion is FALSE # ERROR: tc02t001.cpp, 308: enteredEventsCount == 3 # verified assertion is FALSE It means that the enterEventsCount/enteredEventsCount values were somehow miscounted. My guess is one of the monitor sync point somehow passed without a contention. Most likely, the contention is missed for this fragment (the first one): waitingBarrier1.waitFor(); synchronized (M) { // tc02t001.c::lines[0] M.notify(); }
20-06-2019
I wonder if this can be a dup of the JDK-8217348.
20-06-2019
I've not been able to reproduce it so far. The error message: # ERROR: tc02t001.cpp, 126: line == lines[enterEventsCount] || line == (lines[enterEventsCount] + 1) # verified assertion is FALSE # ERROR: tc02t001.cpp, 129: MonitorContendedEnter event: thread=0000002C997169D8, object=0000002C997169E0, line=133 refers to this jvmti agent fragment (tc02t001.cpp, 126): 41 static jint lines[] = { 127, 132, 137 }; . . . 125 if (!NSK_VERIFY(line == lines[enterEventsCount] || 126 line == (lines[enterEventsCount] + 1))) { 127 nsk_jvmti_setFailStatus(); 128 NSK_COMPLAIN3("MonitorContendedEnter event: thread=%p, object=%p, line=%d\n", 129 thr, obj, line); 130 } The line=133 in the error message above matches the fragment in the tc02t001.java: 123 public void run() { . . . 131 waitingBarrier2.waitFor(); 132 synchronized (M) { // tc02t001.c::lines[1] 133 M.notify(); <== This line! 134 } The current enterEventsCount value is not printed in the error message. Som, it is not clear what is the enterEventsCount value at the error point. If the value is: enterEventsCount == 1 then it would not fail with this error because the following condition has to be true: (line == lines[enterEventsCount] || line == (lines[enterEventsCount] + 1) It is because: enterEventsCount == 1 (it is our assumption) lines[1] = 132 (it is from here: "static jint lines[] = { 127, 132, 137 }; " ) line == 133 (it is printed in the error message above) So, my guess is that the only chance to hit this error is to have this condition: enterEventsCount != 1 Then it gives us a clue about some kind of unsync condition in the tc02t001.java between the runIt() (Main thread) and tc02t001Thread.run(). I need to meditate on this code a little bit more... :)
20-06-2019