RFR 8030847: java/lang/management/ThreadMXBean/ThreadBlockedCount.java fails intermittently again

[David Holmes]

On 8/01/2014 9:39 PM, Jaroslav Bachorik wrote:
> On 8.1.2014 12:35, David Holmes wrote:
>> On 8/01/2014 7:51 PM, Jaroslav Bachorik wrote:
>>> On 8.1.2014 10:26, David Holmes wrote:
>>>>>> getBlockedCount(): Returns the total number of times that the thread
>>>>>> associated with this ThreadInfo blocked to enter or reenter a
>>>>>> monitor.
>>>>>>
>>>>>> None of CyclicBarrier/Phaser etc are monitors, so the BlockedCount
>>>>>> should not be being updated. If it is then that is a spec or
>>>>>> implementation bug in itself :(
>>>>>
>>>>> Indeed, it seems so. I've run the test with JFR enabled and one can
>>>>> distinctively see that the test fails when the thread is parked as it
>>>>> puts the thread into the "blocked" state in the end. I've also patched
>>>>> JVM (the attached monitor-contention.patch; applies to the hotspot
>>>>> repository) to report the thread going into "blocked" state and
>>>>> printing
>>>>> the actual stack trace at that moment and it also shows that the
>>>>> thread
>>>>> goes to "blocked" state somewhere from the "park()" code.
>>>>>
>>>>> I am attaching the JFR recordings - one for the failing test and one
>>>>> for
>>>>> the successful test.
>>>>>
>>>>> IMO, it seems that the ThreadInfo was not updated to reflect the
>>>>> introduction of the park()/unpark() methods. In the current state it
>>>>> mistakenly reports parking a thread as blocking but if the
>>>>> implementation is updated to include only blocking on monitor entry
>>>>> (to
>>>>> correspond to the API docs) we will miss the information about the
>>>>> thread being parked (when the thread also does not execute any user
>>>>> code). This would most probably call for the update of ThreadInfo API.
>>>>
>>>> park() puts you in Thread.State WAITING which is exposed via
>>>> ThreadInfo.getWaitedCount, so I don't see any issue there. If
>>>> parking is
>>>> causing a change to the blocked count then that is a major bug in the
>>>> underlying MXBean implementation.
>>>
>>> Ok, so there must be something else. According the debug output I added
>>> to share/vm/services/threadService.hpp in contended_enter_begin(thread)
>>> method I can see the thread being blocked here:
>>
>> Was the debug output System.out/err.println? It uses synchronization
>> internally so your debug statements may be the cause of the extra block
>> count updates.
>
> No. The output comes from inside the VM native code. Using tty->print().

Okay.

> But the contention handler method contended_enter_begin(thrd) enters
> before any output is generated.

It should be easy enough to report the stack whenever the blocked count 
is updated for a thread.

David (signing off for the night)
-----

> I removed all the System.out/err.println() statements from the test code
> because they were causing much more blocked events.
>
> -JB-
>
>>
>> David
>> -----
>>
>>> 1. Might be related to class loading? The code being called at the
>>> reported line is "LockSupport.unpark(t)"
>>> ***
>>> Blocking on object [I
>>> =============================================================
>>> [Contended thread] BlockedThread
>>>      at java.util.concurrent.Phaser.releaseWaiters(Phaser.java:982)
>>>      at
>>> java.util.concurrent.Phaser.arriveAndAwaitAdvance(Phaser.java:705)
>>>      at
>>> threads.ThreadBlockedCount1$BlockedThread.run(ThreadBlockedCount1.java:99)
>>>
>>>
>>> [Blocked count] 1
>>> ***
>>>
>>> 2. This report is missing information about the lock and the contended
>>> thread. I was not able to figure out how to easily print the information
>>> if the current thread is not the contended thread
>>> ***
>>> at java.util.concurrent.Phaser.internalAwaitAdvance(Phaser.java:1067)
>>>      at
>>> java.util.concurrent.Phaser.arriveAndAwaitAdvance(Phaser.java:690)
>>>      at
>>> threads.ThreadBlockedCount1$BlockedThread.run(ThreadBlockedCount1.java:104)
>>>
>>>
>>>      - locked <0x00000000d6e108e0> (a java.lang.Object)
>>> [Blocked count] 1
>>> ***
>>>
>>>
>>> One of those reports can be seen in the debug output when the test
>>> fails.
>>>
>>> -JB-
>>>
>>>>
>>>> David
>>>> -----
>>>>
>>>>> -JB-
>>>>>
>>>>>>
>>>>>> David
>>>>>
>>>
>