[prev in list] [next in list] [prev in thread] [next in thread] 

List:       openjdk-serviceability-dev
Subject:    Re: RFR 8064441: java/lang/management/ThreadMXBean/Locks.java fails intermittently, blocked on wrong
From:       Jaroslav Bachorik <jaroslav.bachorik () oracle ! com>
Date:       2014-12-05 12:04:04
Message-ID: 54819F34.3080104 () oracle ! com
[Download RAW message or body]

On 12/05/2014 02:19 AM, David Holmes wrote:
> On 3/12/2014 1:51 AM, Jaroslav Bachorik wrote:
>> On 12/02/2014 10:37 AM, David Holmes wrote:
>>> On 1/12/2014 7:16 PM, Jaroslav Bachorik wrote:
>>>> On 11/27/2014 09:33 AM, Jaroslav Bachorik wrote:
>>>>> On 11/27/2014 01:43 AM, David Holmes wrote:
>>>>>> On 26/11/2014 10:57 PM, Jaroslav Bachorik wrote:
>>>>>>> Please, review the following test change
>>>>>>>
>>>>>>> Issue : https://bugs.openjdk.java.net/browse/JDK-8064441
>>>>>>> Webrev: http://cr.openjdk.java.net/~jbachorik/8064441/webrev.00
>>>>>>>
>>>>>>> The test fails because of System.out.println() may induce unexpected
>>>>>>> locking. The solution is to use an already existing
>>>>>>> LockFreeLogManager
>>>>>>> library class to collect the logs in the lock-free manner and print
>>>>>>> the
>>>>>>> logs only after all the test code has been run.
>>>>>>
>>>>>> I seem to remember spending a lot of time on this test in the past,
>>>>>> where the phaser usage was intended to ensure that we could not be
>>>>>> seen
>>>>>> to be blocking on the internal locks associated with the println.
>>>>>> Where
>>>>>> has this gone wrong?
>>>>>
>>>>> The remaining problem is the usage of System.out.print[ln]() inside
>>>>> the
>>>>> test threads. System.out.print[ln]() might involve blocking the
>>>>> calling
>>>>> thread and eg. create false positives when the test is waiting for a
>>>>> thread to enter the blocked state.
>>>>>
>>>>>>
>>>>>> What are the semantics of the lockfreelogger? When will we see its
>>>>>> output?
>>>>>
>>>>> It is using thread local lists of the logging records. Each logging
>>>>> record has an id which is unique and monotonous over all the
>>>>> threads ->
>>>>> an AtomicInteger instance is used to achieve this.
>>>>>
>>>>> You can retrieve the log output (ordered by the log record id) by
>>>>> calling LockFreeLogManager.toString().
>>>>>
>>>>> Review for the LockFreeLogManager is available here
>>>>> [http://mail.openjdk.java.net/pipermail/serviceability-dev/2014-November/015848.html]
>>>>>
>>>>>
>>>>>
>>>>>
>>>>
>>>> David, are you ok with this change then?
>>>
>>> I guess so.  Still not sure why we see the println problem though - but
>>> don't have time to delve into it.
>>
>> Thanks!
>>
>> PrintStream and Writer are full of synchronized blocks. When on use them
>> in multithreaded environment an occasional blocking might occur.
>>
>> For example, in Locks.java, 'LockAThread' and 'LockBThread' threads run
>> concurrently, both of them outputting some log info via System.out. So
>> it may happen that when asserting the 'LockAThread' thread state in
>> 'checkBlockedObject' the thread is in blocked state thanks to blocking
>> on the output stream internals rather than on the test monitor.
>
> Yes but that is what the Phaser is supposed to prevent - the logging
> occurs prior to the phaser actions.

I would be lying if I told I knew exactly where the contention was 
happening. But when I removed the logging completely I wasn't able to 
reproduce the failure in 500 subsequent runs (usually it took up to 100 
runs to encounter the failure) and from that and the fact that there is 
no other place the contention could take place, short of the Phaser 
itself, I deduced that the logging was the culprit. With the new 
collecting ("lock-free") logger the test also runs without the failure 
in 500 runs so I suppose it was the logging.

-JB-

>
> David
>
>> I hope this clarifies the problem a bit.
>>
>> -JB-
>>
>>>
>>> Thanks,
>>> David
>>>
>>>> Thanks,
>>>>
>>>> -JB-
>>>>
>>>>>
>>>>>
>>>>> -JB-
>>>>>
>>>>>>
>>>>>> Thanks,
>>>>>> David
>>>>>>
>>>>>>> Thanks,
>>>>>>>
>>>>>>> -JB-
>>>>>
>>>>
>>

[prev in list] [next in list] [prev in thread] [next in thread]