RFR(M): 8069412 : Locks need better debug-printing support

[Vladimir Kozlov]

Hi David,

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.

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().

Also I don't think you need "_debug" in then name 
LockNode::is_nested_lock_region_debug().

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()) {

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