JDK-8223736 : jvmti/scenarios/contention/TC04/tc04t001/TestDescription.java 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-05-10
  • Updated: 2023-01-10
  • Resolved: 2019-06-21
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 :  
JDK-8226595 - jvmti/scenarios/contention/TC04/tc04t001/TestDescription.java still fails due to wrong number of MonitorContendedEntered events
Relates :  
JDK-8217348 - assert(thread->is_Java_thread()) failed: just checking
Relates :  
JDK-8226595 - jvmti/scenarios/contention/TC04/tc04t001/TestDescription.java still fails due to wrong number of MonitorContendedEntered events
Relates :  
JDK-8224555 - vmTestbase/nsk/jvmti/scenarios/contention/TC02/tc02t001/TestDescription.java failed
Relates :  
JDK-8226638 - Return of jvmti/scenarios/contention/TC04/tc04t001/TestDescription.java fails due to wrong number of MonitorContendedEntered events
Description
The following test failed in the JDK13 CI:

vmTestbase/nsk/jvmti/scenarios/contention/TC04/tc04t001/TestDescription.java

Here's a snippet of the log file:

#section:main
----------messages:(4/292)----------
command: main -agentlib:tc04t001=-waittime=5 nsk.jvmti.scenarios.contention.TC04.tc04t001
reason: User specified action: run main/othervm/native -agentlib:tc04t001=-waittime=5 nsk.jvmti.scenarios.contention.TC04.tc04t001 
Mode: othervm [/othervm specified]
elapsed time (seconds): 16.187
----------configuration:(0/0)----------
----------System.out:(12/674)----------
Started recording 1. No limit specified, using maxsize=250MB as default.

Use jcmd 35000 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: (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: 197
# ERROR: tc04t001.cpp, 275: enteredEventsCount == 199
#   verified assertion is FALSE
# ERROR: tc04t001.cpp, 278: Number of MonitorContendedEntered events: 197
----------System.err:(0/0)----------
----------rerun:(36/5854)*----------
Comments
As this bug has been resolved but we're still seeing the problem, I created a new bug: JDK-8226638. [Later] Never mind, I missed the followup clone: JDK-8226595.
22-06-2019
[~dcubed] Thanks, Dan! Will take a look. This is the most interesting fragment from the output: ``` 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 ```
21-06-2019
URL: http://hg.openjdk.java.net/jdk/jdk13/rev/a3e3f3caf284 User: sspitsyn Date: 2019-06-21 06:13:24 +0000
21-06-2019
Now I think, it is a test issue. Thanks to Alex for helping with the test analysis. It is so much better to have another pair of eyes! The suggested fix is: diff -r f74f0d3033a9 test/hotspot/jtreg/vmTestbase/nsk/jvmti/scenarios/contention/TC04/tc04t001.java --- a/test/hotspot/jtreg/vmTestbase/nsk/jvmti/scenarios/contention/TC04/tc04t001.java Wed Jun 05 22:19:09 2019 -0700 +++ b/test/hotspot/jtreg/vmTestbase/nsk/jvmti/scenarios/contention/TC04/tc04t001.java Wed Jun 19 17:50:12 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 @@ -69,7 +69,11 @@ try { for (int i = 0; i < THREADS_LIMIT; i++) { - threads[i].join(timeout/THREADS_LIMIT); + threads[i].join(timeout); + if (!threads[i].done) { + String msg = "Thread-" + i + " was interrupted by timeout!"; + throw new RuntimeException(msg); + } } } catch (InterruptedException e) { throw new Failure(e); @@ -112,6 +116,7 @@ final static int INCREMENT_LIMIT = 100; final static int DELAY = 1000; + static volatile boolean done; static volatile int value = 0; static Flicker flicker = new Flicker(); @@ -122,6 +127,8 @@ */ private int id; + private static volatile int lastEnterEventsCount; + private static native int enterEventsCount(); public tc04t001Thread(int i) { super("Debuggee Thread " + i); @@ -131,11 +138,13 @@ public synchronized void run() { for (int i = 0; i < INCREMENT_LIMIT; i++) { flicker.waitFor(id); + lastEnterEventsCount = enterEventsCount(); increment(id); try { wait(1); } catch (InterruptedException e) {} } + done = true; } static synchronized void increment(int i) { @@ -144,10 +153,24 @@ */ flicker.unlock(i); int temp = value; - for (int j = 0; j < DELAY; j++) ; - try { - sleep(500); - } catch (InterruptedException e) {} + + // Wait in a loop for a MonitorContendedEnter event. + // Timeout is: 20ms * DELAY. + for (int j = 0; j < DELAY; j++) { + try { + sleep(20); + } catch (InterruptedException e) {} + + if (enterEventsCount() == lastEnterEventsCount + 1) { + break; // Got an expected MonitorContendedEnter event + } + } + System.out.println("Thread-" + i + ": increment event: " + (lastEnterEventsCount + 1)); + + if (enterEventsCount() != lastEnterEventsCount + 1) { + String msg = "Timeout in waiting for a MonitorContendedEnter event"; + throw new RuntimeException(msg); + } value = temp + 1; } } diff -r f74f0d3033a9 test/hotspot/jtreg/vmTestbase/nsk/jvmti/scenarios/contention/TC04/tc04t001/tc04t001.cpp --- a/test/hotspot/jtreg/vmTestbase/nsk/jvmti/scenarios/contention/TC04/tc04t001/tc04t001.cpp Wed Jun 05 22:19:09 2019 -0700 +++ b/test/hotspot/jtreg/vmTestbase/nsk/jvmti/scenarios/contention/TC04/tc04t001/tc04t001.cpp Wed Jun 19 17:50:12 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 @@ -344,6 +344,11 @@ return JNI_OK; } +JNIEXPORT jint JNICALL +Java_nsk_jvmti_scenarios_contention_TC04_tc04t001Thread_enterEventsCount(JNIEnv* jni, jclass klass) { + return enterEventsCount; +} + /* ========================================================================== */ }
20-06-2019
There is pretty good chance that this issue is related or a dup of the JDK-8217348 which has been just fixed (June 17) by Daniil. My suggestion is to wait for a week or two to make sure this problem is still present or disappeared in the CI.
18-06-2019
Looks like this failure shows up several times, so I added the maintainer-pain label.
18-06-2019
JDK-8217348 is not the same failure mode, but it is the same test. Interesting...
10-05-2019