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
