RFR(M): 8069412 : Locks need better debug-printing support
Vladimir Kozlov
vladimir.kozlov at oracle.com
Tue Feb 17 15:47:24 UTC 2015
Yes, this looks good.
Thanks,
Vladimir
On 2/17/15 5:22 AM, David Chase wrote:
> This time for sure...
>
> http://cr.openjdk.java.net/~drchase/8069412/webrev.04/
>
> Fixed style notes from Vladimir and David,
> reworked log_lock_optimization to take a Compile *, modified callers,
> therefore also reworked the debugging-general form of is_nested_lock_region to take a Compile *
> and its callers.
>
> Retested w/ jtreg -XX:+LogCompilation to be sure I had not typoed,
> also reran one of my one-off tests for lock optimization and checked its logged+formatted output.
>
> David
>
> On 2015-02-16, at 7:15 PM, Vladimir Kozlov <vladimir.kozlov at oracle.com> wrote:
>
>> Yes, Compile is Phase's subclass but 'C' field is NULL:
>>
>> Phase::Phase( PhaseNumber pnum ) : _pnum(pnum), C( pnum == Compiler ? NULL : Compile::current()) {
>>
>> So you can't pass C as phase into log_lock_optimization() and is_nested_lock_region(). I suggest to use Compile*.
>>
>> Style is not fixed:
>>
>> + if (monitor->eliminated())
>> + if(is_compiled_frame())
>> + tty->print(" ( lock is eliminated in compiled frame )");
>> + else
>> + tty->print(" ( lock is eliminated, frame not compiled )");
>>
>> Vladimir
>>
>> On 2/16/15 10:09 AM, David Chase wrote:
>>> Improved webrev, should address issues:
>>>
>>> http://cr.openjdk.java.net/~drchase/8069412/webrev.03/
>>>
>>> I did some more work on LogCompilation -- testing (there is none for that tool in jtreg or JPRT)
>>> revealed that the 9+changes tool would crash on 8u logs, and that (1) made it hard for me to test
>>> my changes against existing logs known to contain new-features data and (2) seems kinda graceless
>>> anyhow.
>>>
>>> David
>>>
>>> On 2015-02-13, at 11:50 AM, Vladimir Kozlov <vladimir.kozlov at oracle.com> wrote:
>>>
>>>> On 2/13/15 5:33 AM, David Chase wrote:
>>>>>> In general I am fine with this changes. There are styles issues, indention (used 4 bytes instead of 2). Other then that I have only few comments.
>>>>>
>>>>> markOop.cpp? Fixed it.
>>>>
>>>> Also basicLock.cpp and vframe.cpp. They also miss {} for new if statements.
>>>>
>>>>> LogCompilation files are java and 4-character indent by default.
>>>>>
>>>>>> In vframe.cpp why you cloned print_locked_object_class_name() to all passes. Instead you could set Boolean local in inner scope if you want to print Verbose output after print_locked_object_class_name().
>>>>>
>>>>> "mark" was not in scope outside, it seemed cleaner on balance just to clone the call.
>>>>
>>>> You can set 'markOop mark = NULL' before 'if (!found_first_monitor' and use 'if (Verbose && (mark != NULL))' condition to print additional info. I don't think to have 3 copy of code is clean.
>>>>
>>>>>
>>>>>> Also I don't think you need "_debug" in then name LockNode::is_nested_lock_region_debug().
>>>>>
>>>>> I wanted it to be clear that this was only for debugging -- it is clone of the previous method with tracing in the failure paths.
>>>>
>>>> Why duplicate code that to do logging. Note, the logging is available in product VM too. I would suggest to modify the original method to do logging. You can pass additional bool argument to trigger logging if you don't want to do it always.
>>>>
>>>>>
>>>>>> You only need to add additional check is_Lock() in debug mode where before we may only check jvms() != NULL. I think you simply can add explicit check in macro.cpp code:
>>>>>>
>>>>>> ! // Not that preceding claim is documented anywhere else.
>>>>>> ! if (alock->jvms() != NULL && alock->is_Lock()) {
>>>>>> ! if (alock->as_Lock()->is_nested_lock_region()) {
>>>>>
>>>>> I didn't change jvms() assignment -- for Unlock nodes there is a debug-only second field to hold this information,
>>>>> because this is not the only place sensitive to which AbstractLock nodes have jvms() attached, and adding a jvms()
>>>>> to Unlock nodes caused additional failures. So the original condition still works.
>>>>
>>>> Okay, I got it.
>>>>
>>>> Thanks,
>>>> Vladimir
>>>>
>>>>>
>>>>> thanks for the review,
>>>>>
>>>>> David
>>>>>
>>>>>> Thanks,
>>>>>> Vladimir
>>>>>>
>>>>>> On 2/12/15 7:09 PM, David Chase wrote:
>>>>>>> http://cr.openjdk.java.net/~drchase/8069412/webrev.00/
>>>>>>>
>>>>>>> This is the debugging support that I found very helpful to make progress on
>>>>>>> https://bugs.openjdk.java.net/browse/JDK-8066576 "Lock still held"
>>>>>>>
>>>>>>> It comes in three parts:
>>>>>>>
>>>>>>> 1) When -XX:+Verbose, locks in stack backtrace are printed with additional information,
>>>>>>> like so:
>>>>>>>
>>>>>>> "FooThread" #19 daemon prio=10 os_prio=31 tid=0x00007fe41c2c8000 nid=0x6203 waiting for monitor entry [0x0000000110072000]
>>>>>>> java.lang.Thread.State: BLOCKED (on object monitor)
>>>>>>> JavaThread state: _thread_blocked
>>>>>>> Thread: 0x00007fe41c2c8000 [0x6203] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0
>>>>>>> JavaThread state: _thread_blocked
>>>>>>> at foo.Foo.send(Foo.java:21)
>>>>>>> - waiting to lock <0x0000000780b89008> (a java.lang.Object)
>>>>>>> lockbits= locked(0x00007fe41c23d09a)->monitor={count=0x0000000000000001,waiters=0x0000000000000000,recursions=0x0000000000000000,owner=0x00007fe41b8fc000}
>>>>>>> at foo.Bar.bar(Bar.java:1)
>>>>>>>
>>>>>>> The new line is the one beginning " lockbits".
>>>>>>> Without -XX:+Verbose, the old behavior remains.
>>>>>>>
>>>>>>> 2) In a debug (#ifdef ASSERT) build, when -XX+:LogCompilation is specified,
>>>>>>> additional records are written to the compilation log file describing which lock optimizations
>>>>>>> are performed (and in some cases, which are not performed, and why).
>>>>>>>
>>>>>>> For example:
>>>>>>>
>>>>>>> <eliminate_lock_set_nested lock='0' compile_id='1840' class_id='unlock' kind='?' stamp='350.736'>
>>>>>>> </eliminate_lock_set_nested>
>>>>>>> <eliminate_lock_set_nested lock='1' compile_id='1840' class_id='lock' kind='coarsened' stamp='350.736'>
>>>>>>> </eliminate_lock_set_nested>
>>>>>>>
>>>>>>> where the first record indicates that a previously unoptimized lock (kind='?') was set to 'nested'
>>>>>>> and the second record indicates that a previously coarsened lock was set to nested.
>>>>>>> Other additional information recorded includes locations for Unlock nodes.
>>>>>>>
>>>>>>> Even in release builds, the kind of elimination (nested, coarsened, non-escaping) is now noted.
>>>>>>>
>>>>>>> 3) The compilation processing tool was enhanced to process these new records, producing output like this:
>>>>>>>
>>>>>>> 1783 eliminate_lock_NOT_nested_lock_region ? lock 98.713 [@36 foo.Foo::fooMethod (330 bytes)]
>>>>>>> 1783 eliminate_lock_INLR_1 ? lock 98.713 [@36 foo.Foo::fooMethod (330 bytes)]
>>>>>>> 1783 eliminate_lock_set_nested ? unlock 98.713 [@-1 bar.BAR::setData (53 bytes), @54 foo.Foo::fooMethod (330 bytes)]
>>>>>>> 1783 eliminate_lock_set_nested ? lock 98.713 [@-1 bar.BAR::setData (53 bytes), @54 foo.Foo::fooMethod (330 bytes)]
>>>>>>> 1783 eliminate_lock_set_nested nested lock 98.713 [@-1 bar.BAR::setData (53 bytes), @54 foo.Foo::fooMethod (330 bytes)]
>>>>>>> 1783 eliminate_lock_set_nested ? unlock 98.713 [@-1 bar.BAR::getLength (5 bytes), @65 foo.Foo::fooMethod (330 bytes)]
>>>>>>> 1783 eliminate_lock_set_nested ? lock 98.713 [@-1 bar.BAR::getLength (5 bytes), @65 foo.Foo::fooMethod (330 bytes)]
>>>>>>> 1783 eliminate_lock_set_nested nested lock 98.713 [@-1 bar.BAR::getLength (5 bytes), @65 foo.Foo::fooMethod (330 bytes)]
>>>>>>> 1783 eliminate_lock_NOT_nested_lock_region ? lock 98.713 [@202 foo.Foo::fooMethod (330 bytes)]
>>>>>>> 1783 eliminate_lock_INLR_1 ? lock 98.713 [@202 foo.Foo::fooMethod (330 bytes)]
>>>>>>> 1783 eliminate_lock nested unlock 98.713 [@-1 bar.BAR::getLength (5 bytes), @65 foo.Foo::fooMethod (330 bytes)]
>>>>>>> 1783 eliminate_lock nested lock 98.713 [@-1 bar.BAR::getLength (5 bytes), @65 foo.Foo::fooMethod (330 bytes)]
>>>>>>> 1783 eliminate_lock nested unlock 98.714 [@-1 bar.BAR::setData (53 bytes), @54 foo.Foo::fooMethod (330 bytes)]
>>>>>>> 1783 eliminate_lock nested lock 98.714 [@-1 bar.BAR::setData (53 bytes), @54 foo.Foo::fooMethod (330 bytes)]
>>>>>>>
>>>>>>> This was tested running jtreg on compiler and runtime,
>>>>>>> as well as many runs of the problematic application for 8066576,
>>>>>>> plus JPRT of the hotspot testsuite,
>>>>>>> plus built with XCode 4.6.3 and 6.1.1 on Mavericks and gcc 4.8.2 on Ubuntu 14.04.
>>>>>>>
>>>>>>> David
>>>>>>>
>>>>>>>
>>>>>
>>>
>
More information about the hotspot-runtime-dev
mailing list