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

[David Chase]

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


-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 801 bytes
Desc: Message signed with OpenPGP using GPGMail
URL: <http://mail.openjdk.java.net/pipermail/hotspot-compiler-dev/attachments/20150212/0c25434c/signature-0001.asc>