JDK-8320561 : Inconsistency in monitorinflation logging
  • Type: Bug
  • Component: hotspot
  • Sub-Component: runtime
  • Affected Version: 22
  • Priority: P4
  • Status: Resolved
  • Resolution: Fixed
  • Submitted: 2023-11-21
  • Updated: 2024-08-05
  • Resolved: 2024-07-30
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 24
24 b09Fixed
Related Reports
Relates :  
JDK-8320515 - assert(monitor->object_peek() != nullptr) failed: Owned monitors should not have a dead object
Relates :  
JDK-8319896 - Remove monitor deflation from final audit
Description
While investigating JDK-8320515 I noticed this inconsistency in the -Xlog:monitorinflation logging output:

[35.415s][trace][monitorinflation] Checking in_use_list:
[35.415s][trace][monitorinflation] count=4, max=4
[35.415s][trace][monitorinflation] in_use_count=4 equals ck_in_use_count=4
[35.415s][trace][monitorinflation] in_use_max=4 equals ck_in_use_max=4
[35.415s][trace][monitorinflation] No errors found in in_use_list checks.
[35.415s][trace][monitorinflation] In-use monitor info:
[35.415s][trace][monitorinflation] (B -> is_busy, H -> has hash code, L -> lock status)
[35.416s][trace][monitorinflation]            monitor  BHL              object         object type
[35.416s][trace][monitorinflation] ==================  ===  ==================  ==================
[35.416s][trace][monitorinflation] 0x00007efd38002190  000  0x000000041592bd78  CompleteExit$2
[35.416s][trace][monitorinflation] 0x00007efd380020a0  000  0x000000041592bbb0  CompleteExit$1
[35.416s][trace][monitorinflation] 0x00007efe08324bb0  010  0x000000041592a918  java.lang.Thread
[35.416s][trace][monitorinflation] 0x00007efd640010b0  100  0x0000000415909f38  java.lang.ref.NativeReferenceQueue$Lock (is_busy: waiters=1, contentions=0, owner=0x0000000000000000, cxq=0x0000000000000000, EntryList=0x0000000000000000)
[35.463s][info ][monitorinflation] Starting the final audit.
[35.463s][trace][monitorinflation] Checking in_use_list:
[35.463s][trace][monitorinflation] count=4, max=4
[35.463s][trace][monitorinflation] in_use_count=4 equals ck_in_use_count=4
[35.463s][trace][monitorinflation] in_use_max=4 equals ck_in_use_max=4
[35.463s][trace][monitorinflation] No errors found in in_use_list checks.
[35.463s][trace][monitorinflation] In-use monitor info:
[35.463s][trace][monitorinflation] (B -> is_busy, H -> has hash code, L -> lock status)
[35.463s][trace][monitorinflation]            monitor  BHL              object         object type
[35.463s][trace][monitorinflation] ==================  ===  ==================  ==================
[35.463s][trace][monitorinflation] 0x00007efd640010b0  100  0x0000000415909f38  java.lang.ref.NativeReferenceQueue$Lock (is_busy: waiters=1, contentions=0, owner=0x0000000000000000, cxq=0x0000000000000000, EntryList=0x0000000000000000)

Note that initially we have 4 in-use monitors and we list all 4 of them. But then some are released and we only list the remaining  java.lang.ref.NativeReferenceQueue$Lock monitor, but the count still says 4.

[35.463s][trace][monitorinflation] count=4, max=4
[35.463s][trace][monitorinflation] in_use_count=4 equals ck_in_use_count=4
Comments
Changeset: d39e7af2 Branch: master Author: David Holmes <dholmes@openjdk.org> Date: 2024-07-30 22:35:14 +0000 URL: https://git.openjdk.org/jdk/commit/d39e7af2e5d28df43c0b2dad770f41adede5cc29
30-07-2024
A pull request was submitted for review. Branch: master URL: https://git.openjdk.org/jdk/pull/20387 Date: 2024-07-30 07:47:46 +0000
30-07-2024
Output before: [0.195s][info ][monitorinflation] Starting the final audit. [0.195s][info ][monitorinflation] Checking in_use_list: [0.195s][info ][monitorinflation] count=2, max=2 [0.195s][info ][monitorinflation] in_use_count=2 equals ck_in_use_count=2 [0.195s][info ][monitorinflation] in_use_max=2 equals ck_in_use_max=2 [0.195s][info ][monitorinflation] No errors found in in_use_list checks. [0.195s][info ][monitorinflation] In-use monitor info: [0.195s][info ][monitorinflation] (B -> is_busy, H -> has hash code, L -> lock status) [0.195s][info ][monitorinflation] monitor BHL object object type [0.195s][info ][monitorinflation] ================== === ================== ================== [0.195s][info ][monitorinflation] 0x00007fd040001010 100 0x0000000456002480 java.lang.ref.NativeReferenceQueue$Lock (is_busy: waiters=1, contentions=0, owner=0x0000000000000000, cxq=0x0000000000000000, EntryList=0x0000000000000000) Output after: [0.197s][info ][monitorinflation] Starting the final audit. [0.197s][info ][monitorinflation] Checking in_use_list: [0.197s][info ][monitorinflation] count=2, max=2 [0.197s][info ][monitorinflation] in_use_count=2 equals ck_in_use_count=2 [0.197s][info ][monitorinflation] in_use_max=2 equals ck_in_use_max=2 [0.197s][info ][monitorinflation] No errors found in in_use_list checks. [0.197s][info ][monitorinflation] In-use monitor info (eliding idle monitors): [0.197s][info ][monitorinflation] (B -> is_busy, H -> has hash code, L -> lock status) [0.197s][info ][monitorinflation] monitor BHL object object type [0.197s][info ][monitorinflation] ================== === ================== ================== [0.197s][info ][monitorinflation] 0x00007f857c001010 100 0x0000000456002480 java.lang.ref.NativeReferenceQueue$Lock (is_busy: waiters=1, contentions=0, owner=0x0000000000000000, cxq=0x0000000000000000, EntryList=0x0000000000000000) This line: [0.195s][info ][monitorinflation] In-use monitor info: becomes [0.197s][info ][monitorinflation] In-use monitor info (eliding idle monitors):
30-07-2024
Mystery solved. The changes recently pushed under JDK-8319896 skip printing "uninteresting" monitors i.e. idle ones, as it now skips the deflation step that would have removed them previously. Maybe we can just augment the header info from out->print_cr("In-use monitor info:"); to out->print_cr("In-use monitor info (eliding idle monitors):"); but taking into account the "log_all" parameter. It would be nice to know how many are elided but we don't know that when we print this header line.
22-11-2023