Bug ID: JDK-8306774 Make runtime/Monitor/GuaranteedAsyncDeflationIntervalTest.java more reliable

JDK-8306774 : Make runtime/Monitor/GuaranteedAsyncDeflationIntervalTest.java more reliable

Type: Bug
Component: hotspot
Sub-Component: runtime
Affected Version: 17,20,21

Priority: P3
Status: Resolved
Resolution: Fixed
OS: os_x
CPU: x86_64,aarch64

Submitted: 2023-04-24
Updated: 2023-09-19
Resolved: 2023-04-26

Versions (Unresolved/Resolved/Fixed)

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 17	JDK 20	JDK 21
17.0.10-oracleFixed	20.0.2Fixed	21 b20Fixed

Related Reports

Relates :

JDK-8305994 - Guarantee eventual async monitor deflation

Sub Tasks

JDK-8306775 :

Problemlist runtime/Monitor/GuaranteedAsyncDeflationIntervalTest.java - Resolved

Description

The following new test is failing in the JDK21 CI:

runtime/Monitor/GuaranteedAsyncDeflationIntervalTest.java#allEnabled

Here's a snippet from the log file:

----------System.err:(98/9947)----------
 stdout: [[5.824s][info][monitorinflation] Async deflation needed: guaranteed interval (5000 ms) is greater than time since last deflation (5815 ms)
[5.824s][info][monitorinflation] begin deflating: in_use_list stats: ceiling=11264, count=1123, max=1123
[5.824s][info][monitorinflation] before handshaking: unlinked_count=1121, in_use_list stats: ceiling=11264, count=2, max=1123
[5.824s][info][monitorinflation] after handshaking: in_use_list stats: ceiling=11264, count=2, max=1123
[5.825s][info][monitorinflation] deflated_count=1121, {unlinked,deleted}_count=1121 monitors in 0.0003808 secs
[5.825s][info][monitorinflation] end deflating: in_use_list stats: ceiling=11264, count=2, max=1123
[11.571s][info][monitorinflation] Async deflation needed: guaranteed interval (5000 ms) is greater than time since last deflation (5746 ms)
[11.571s][info][monitorinflation] begin deflating: in_use_list stats: ceiling=11264, count=1012, max=1123
[11.571s][info][monitorinflation] before handshaking: unlinked_count=1010, in_use_list stats: ceiling=11264, count=2, max=1123
[11.571s][info][monitorinflation] after handshaking: in_use_list stats: ceiling=11264, count=2, max=1123
[11.571s][info][monitorinflation] deflated_count=1010, {unlinked,deleted}_count=1010 monitors in 0.0003291 secs
[11.571s][info][monitorinflation] end deflating: in_use_list stats: ceiling=11264, count=2, max=1123
[17.314s][info][monitorinflation] Async deflation needed: guaranteed interval (5000 ms) is greater than time since last deflation (5743 ms)
[17.314s][info][monitorinflation] begin deflating: in_use_list stats: ceiling=11264, count=1076, max=1123
[17.314s][info][monitorinflation] before handshaking: unlinked_count=1074, in_use_list stats: ceiling=11264, count=3, max=1123
[17.314s][info][monitorinflation] after handshaking: in_use_list stats: ceiling=11264, count=3, max=1123
[17.314s][info][monitorinflation] deflated_count=1074, {unlinked,deleted}_count=1074 monitors in 0.0003861 secs
[17.314s][info][monitorinflation] end deflating: in_use_list stats: ceiling=11264, count=3, max=1123
[22.885s][info][monitorinflation] Async deflation needed: guaranteed interval (5000 ms) is greater than time since last deflation (5571 ms)
[22.885s][info][monitorinflation] begin deflating: in_use_list stats: ceiling=11264, count=718, max=1123
[22.885s][info][monitorinflation] before handshaking: unlinked_count=717, in_use_list stats: ceiling=11264, count=2, max=1123
[22.885s][info][monitorinflation] after handshaking: in_use_list stats: ceiling=11264, count=2, max=1123
[22.886s][info][monitorinflation] deflated_count=717, {unlinked,deleted}_count=717 monitors in 0.0002403 secs
[22.886s][info][monitorinflation] end deflating: in_use_list stats: ceiling=11264, count=2, max=1123
[28.399s][info][monitorinflation] Async deflation needed: guaranteed interval (5000 ms) is greater than time since last deflation (5514 ms)
[28.399s][info][monitorinflation] begin deflating: in_use_list stats: ceiling=11264, count=1083, max=1123
[28.400s][info][monitorinflation] before handshaking: unlinked_count=1081, in_use_list stats: ceiling=11264, count=2, max=1123
[28.400s][info][monitorinflation] after handshaking: in_use_list stats: ceiling=11264, count=2, max=1123
[28.400s][info][monitorinflation] deflated_count=1081, {unlinked,deleted}_count=1081 monitors in 0.0003843 secs
[28.400s][info][monitorinflation] end deflating: in_use_list stats: ceiling=11264, count=2, max=1123
[34.046s][info][monitorinflation] Async deflation needed: guaranteed interval (5000 ms) is greater than time since last deflation (5647 ms)
[34.046s][info][monitorinflation] begin deflating: in_use_list stats: ceiling=11264, count=1046, max=1123
[34.047s][info][monitorinflation] before handshaking: unlinked_count=1044, in_use_list stats: ceiling=11264, count=3, max=1123
[34.047s][info][monitorinflation] after handshaking: in_use_list stats: ceiling=11264, count=3, max=1123
[34.047s][info][monitorinflation] deflated_count=1044, {unlinked,deleted}_count=1044 monitors in 0.0004321 secs
[34.047s][info][monitorinflation] end deflating: in_use_list stats: ceiling=11264, count=3, max=1123
[39.546s][info][monitorinflation] Async deflation needed: guaranteed interval (5000 ms) is greater than time since last deflation (5499 ms)
[39.546s][info][monitorinflation] begin deflating: in_use_list stats: ceiling=11264, count=929, max=1123
[39.546s][info][monitorinflation] before handshaking: unlinked_count=927, in_use_list stats: ceiling=11264, count=2, max=1123
[39.546s][info][monitorinflation] after handshaking: in_use_list stats: ceiling=11264, count=2, max=1123
[39.547s][info][monitorinflation] deflated_count=927, {unlinked,deleted}_count=927 monitors in 0.0002978 secs
[39.547s][info][monitorinflation] end deflating: in_use_list stats: ceiling=11264, count=2, max=1123
[45.168s][info][monitorinflation] Async deflation needed: guaranteed interval (5000 ms) is greater than time since last deflation (5621 ms)
[45.168s][info][monitorinflation] begin deflating: in_use_list stats: ceiling=11264, count=937, max=1123
[45.168s][info][monitorinflation] before handshaking: unlinked_count=935, in_use_list stats: ceiling=11264, count=3, max=1123
[45.168s][info][monitorinflation] after handshaking: in_use_list stats: ceiling=11264, count=3, max=1123
[45.168s][info][monitorinflation] deflated_count=935, {unlinked,deleted}_count=935 monitors in 0.0003150 secs
[45.168s][info][monitorinflation] end deflating: in_use_list stats: ceiling=11264, count=3, max=1123
[50.531s][info][monitorinflation] Async deflation needed: guaranteed interval (5000 ms) is greater than time since last deflation (5362 ms)
[50.531s][info][monitorinflation] begin deflating: in_use_list stats: ceiling=11264, count=902, max=1123
[50.531s][info][monitorinflation] before handshaking: unlinked_count=900, in_use_list stats: ceiling=11264, count=2, max=1123
[50.531s][info][monitorinflation] after handshaking: in_use_list stats: ceiling=11264, count=2, max=1123
[50.531s][info][monitorinflation] deflated_count=900, {unlinked,deleted}_count=900 monitors in 0.0003153 secs
[50.531s][info][monitorinflation] end deflating: in_use_list stats: ceiling=11264, count=2, max=1123
[56.104s][info][monitorinflation] Async deflation needed: guaranteed interval (5000 ms) is greater than time since last deflation (5573 ms)
[56.104s][info][monitorinflation] begin deflating: in_use_list stats: ceiling=11264, count=1020, max=1123
[56.105s][info][monitorinflation] before handshaking: unlinked_count=1018, in_use_list stats: ceiling=11264, count=3, max=1123
[56.105s][info][monitorinflation] after handshaking: in_use_list stats: ceiling=11264, count=3, max=1123
[56.105s][info][monitorinflation] deflated_count=1018, {unlinked,deleted}_count=1018 monitors in 0.0003662 secs
[56.105s][info][monitorinflation] end deflating: in_use_list stats: ceiling=11264, count=3, max=1123
[61.543s][info][monitorinflation] Async deflation needed: guaranteed interval (5000 ms) is greater than time since last deflation (5438 ms)
[61.543s][info][monitorinflation] begin deflating: in_use_list stats: ceiling=11264, count=174, max=1123
[61.543s][info][monitorinflation] before handshaking: unlinked_count=173, in_use_list stats: ceiling=11264, count=1, max=1123
[61.543s][info][monitorinflation] after handshaking: in_use_list stats: ceiling=11264, count=1, max=1123
[61.543s][info][monitorinflation] deflated_count=173, {unlinked,deleted}_count=173 monitors in 0.0000727 secs
[61.543s][info][monitorinflation] end deflating: in_use_list stats: ceiling=11264, count=1, max=1123
[67.200s][info][monitorinflation] Async deflation needed: guaranteed interval (5000 ms) is greater than time since last deflation (5657 ms)
[67.200s][info][monitorinflation] begin deflating: in_use_list stats: ceiling=11264, count=1, max=1123
[67.200s][info][monitorinflation] end deflating: in_use_list stats: ceiling=11264, count=1, max=1123
[67.326s][info][monitorinflation] Starting the final audit.
[67.326s][info][monitorinflation] begin deflating: in_use_list stats: ceiling=10240, count=1, max=1123
[67.326s][info][monitorinflation] end deflating: in_use_list stats: ceiling=10240, count=1, max=1123
[67.326s][info][monitorinflation] Checking in_use_list:
[67.326s][info][monitorinflation] count=1, max=1123
[67.326s][info][monitorinflation] in_use_count=1 equals ck_in_use_count=1
[67.326s][info][monitorinflation] in_use_max=1123 equals ck_in_use_max=1123
[67.326s][info][monitorinflation] No errors found in in_use_list checks.
[67.326s][info][monitorinflation] In-use monitor info:
[67.326s][info][monitorinflation] (B -> is_busy, H -> has hash code, L -> lock status)
[67.326s][info][monitorinflation]            monitor  BHL              object         object type
[67.326s][info][monitorinflation] ==================  ===  ==================  ==================
[67.326s][info][monitorinflation] 0x00007f8304607540  100  0x00000007ffd01670  java.lang.ref.NativeReferenceQueue$Lock (is_busy: waiters=1, contentions=0owner=0x0000000000000000, cxq=0x0000000000000000, EntryList=0x0000000000000000)
];
 stderr: []
 exitValue = 0

java.lang.RuntimeException: 'Async deflation needed: monitors used are above the threshold' missing from stdout/stderr
	at jdk.test.lib.process.OutputAnalyzer.shouldContain(OutputAnalyzer.java:221)
	at GuaranteedAsyncDeflationIntervalTest.testAllEnabled(GuaranteedAsyncDeflationIntervalTest.java:180)
	at GuaranteedAsyncDeflationIntervalTest.main(GuaranteedAsyncDeflationIntervalTest.java:102)
	at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:103)
	at java.base/java.lang.reflect.Method.invoke(Method.java:578)
	at com.sun.javatest.regtest.agent.MainActionHelper$AgentVMRunnable.run(MainActionHelper.java:333)
	at java.base/java.lang.Thread.run(Thread.java:1592)

JavaTest Message: Test threw exception: java.lang.RuntimeException
JavaTest Message: shutting down test

result: Failed. Execution failed: `main' threw exception: java.lang.RuntimeException: 'Async deflation needed: monitors used are above the threshold' missing from stdout/stderr

Comments

Fix Request (20u, 17u) This fixes the test introduced by JDK-8305994. The patch applies cleanly without the ProblemList changes to both 20u and 17u (see related PRs). Testing, including the affected regression test, passes. JDK-8305994, JDK-8306774, JDK-8306825 all go in together to fix related issues at once.
02-05-2023
A pull request was submitted for review. URL: https://git.openjdk.org/jdk17u-dev/pull/1317 Date: 2023-05-02 10:10:06 +0000
02-05-2023
A pull request was submitted for review. URL: https://git.openjdk.org/jdk20u/pull/70 Date: 2023-05-02 08:57:27 +0000
02-05-2023
Mach5 Tier1 testing for v01: - https://mach5.us.oracle.com/mdash/jobs/dcubed-XXXXXXX_for_jdk21.git-20230425-2044-45050507 - no failures Mach5 Repeat-50 testing of runtime/Monitor/GuaranteedAsyncDeflationIntervalTest.java: - $ mach5 remote-test --build-id 2023-04-25-2041417.daniel.daugherty.XXXXXXX_for_jdk21.git -t 'runtime/Monitor/GuaranteedAsyncDeflationIntervalTest.java' --test-make-args "JTREG_REPEAT_COUNT=50" - linux-aarch64, linux-x64, macosx-x64 and windows-x64 passed all 50 runs - $ mach5 remote-test --build-id 2023-04-25-2041417.daniel.daugherty.XXXXXXX_for_jdk21.git -t 'runtime/Monitor/GuaranteedAsyncDeflationIntervalTest.java' --test-make-args "JTREG_REPEAT_COUNT=50" -b macosx-aarch64 - macosx-aarch64 passed all 50 runs
26-04-2023
Changeset: 9ad6dc88 Author: Aleksey Shipilev <shade@openjdk.org> Date: 2023-04-26 11:11:54 +0000 URL: https://git.openjdk.org/jdk/commit/9ad6dc881d285cc26c136f0ef19af5bac0a75022
26-04-2023
ILW = MMH = P3
25-04-2023
A pull request was submitted for review. URL: https://git.openjdk.org/jdk/pull/13634 Date: 2023-04-25 09:01:13 +0000
25-04-2023
Okay, it is obvious to me I need to rethink the test a bit. Running out of time today, so I'll problemlist it shortly. EDIT: JDK-8306775
24-04-2023
Aha! Seems like we never had a "monitors used are above the threshold" trigger at all, and only the guaranteed one kicked in. From the logs, it looks like the inflation is very, very slow, so every 5 seconds we have about 1K monitors inflated. Which means it is not enough monitors to trigger the threshold heuristics before guaranteed one kicks in. Let me see if I can strengthen the test quickly. Edit: I see why. wait(1) takes ~1ms. So in 5 seconds, we have at about 5K monitors inflated, argh. If the OS is even slower, we can inflate progressively fewer monitors, argh.
24-04-2023
[~shade] - The new test added by: JDK-8305994 Guarantee eventual async monitor deflation is failing in Mach5 Tier1 on macosx-aarch64 and macosx-x64.
24-04-2023