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

[David Holmes]

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.

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
>>>
>