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

[Jaroslav Bachorik]

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(). 
But the contention handler method contended_enter_begin(thrd) enters 
before any output is generated.
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
>>>>
>>