Question about tty lock rank

[David Holmes]

Hi Thomas,

There are known limits on trying to use tty too early, or from certain 
places. I doubt anyone recalls the exact design around the lock rank 
placement and that design has been distorted over time to allow other 
locks to be jammed in to the scheme. Getting rid of, or completely 
re-doing lock ranking, is something we've been musing on for a while now.

Cheers,
David

On 14/02/2019 1:58 am, Thomas Stüfe wrote:
> Hi all,
> 
> Since tty lock rank is 3, this means that we cannot use tty when holding a
> lock whose rank is <= 3, right?
> 
> For analysis reasons, I attempted to call EventLog::print_all(tty) at VM
> exit.
> That asserts right away in Monitor::set_owner_implementation() because
> - event log printing obtains the event log mutex, which has rank 0
> - then we attempt to print to tty, which obtains the tty lock on every call
> to write(), which has rank 3
> (A)
> 
> Ironically, then we attempt to write the owned locks as a debug help, write
> again to tty and now get an owner!=self assert (B).
> 
> (gdb) bt
> #0  0x00007ffff5eca9f2 in Monitor::lock_without_safepoint_check
> (this=0x7ffff0013ae0, self=0x7ffff001c800) at
> /shared/projects/openjdk/jdk-jdk/source/src/hotspot/share/runtime/mutex.cpp:97
> #1  0x00007ffff5ecaa93 in Monitor::lock_without_safepoint_check
> (this=0x7ffff0013ae0) at
> /shared/projects/openjdk/jdk-jdk/source/src/hotspot/share/runtime/mutex.cpp:104
> (B)
> #2  0x00007ffff5f58271 in defaultStream::hold (this=0x7ffff0000930,
> writer_id=25522) at
> /shared/projects/openjdk/jdk-jdk/source/src/hotspot/share/utilities/ostream.cpp:810
> #3  0x00007ffff5f58356 in defaultStream::write (this=0x7ffff0000930,
> s=0x7ffff7fd3660 " Locks owned:\n", len=14) at
> /shared/projects/openjdk/jdk-jdk/source/src/hotspot/share/utilities/ostream.cpp:838
> #4  0x00007ffff5f56035 in
> outputStream::do_vsnprintf_and_write_with_automatic_buffer
> (this=0x7ffff0000930, format=0x7ffff68a6401 " Locks owned:",
> ap=0x7ffff7fd3e98, add_cr=true) at
> /shared/projects/openjdk/jdk-jdk/source/src/hotspot/share/utilities/ostream.cpp:127
> #5  0x00007ffff5f56112 in outputStream::do_vsnprintf_and_write
> (this=0x7ffff0000930, format=0x7ffff68a6401 " Locks owned:",
> ap=0x7ffff7fd3e98, add_cr=true) at
> /shared/projects/openjdk/jdk-jdk/source/src/hotspot/share/utilities/ostream.cpp:140
> #6  0x00007ffff5f5626a in outputStream::print_cr (this=0x7ffff0000930,
> format=0x7ffff68a6401 " Locks owned:") at
> /shared/projects/openjdk/jdk-jdk/source/src/hotspot/share/utilities/ostream.cpp:154
> #7  0x00007ffff6208f06 in Thread::print_owned_locks_on
> (this=0x7ffff001c800, st=0x7ffff0000930) at
> /shared/projects/openjdk/jdk-jdk/source/src/hotspot/share/runtime/thread.cpp:992
> #8  0x00007ffff5ecc325 in Thread::print_owned_locks (this=0x7ffff001c800)
> at
> /shared/projects/openjdk/jdk-jdk/source/src/hotspot/share/runtime/thread.hpp:741
> (A)
> #9  0x00007ffff5ecbc60 in Monitor::set_owner_implementation
> (this=0x7ffff0013ae0, new_owner=0x7ffff001c800) at
> /shared/projects/openjdk/jdk-jdk/source/src/hotspot/share/runtime/mutex.cpp:413
> #10 0x00007ffff5ecc29f in Monitor::set_owner (this=0x7ffff0013ae0,
> owner=0x7ffff001c800) at
> /shared/projects/openjdk/jdk-jdk/source/src/hotspot/share/runtime/mutex.hpp:189
> #11 0x00007ffff5ecaa6c in Monitor::lock_without_safepoint_check
> (this=0x7ffff0013ae0, self=0x7ffff001c800) at
> /shared/projects/openjdk/jdk-jdk/source/src/hotspot/share/runtime/mutex.cpp:100
> #12 0x00007ffff5ecaa93 in Monitor::lock_without_safepoint_check
> (this=0x7ffff0013ae0) at
> /shared/projects/openjdk/jdk-jdk/source/src/hotspot/share/runtime/mutex.cpp:104
> #13 0x00007ffff5f58271 in defaultStream::hold (this=0x7ffff0000930,
> writer_id=25522) at
> /shared/projects/openjdk/jdk-jdk/source/src/hotspot/share/utilities/ostream.cpp:810
> #14 0x00007ffff5f58356 in defaultStream::write (this=0x7ffff0000930,
> s=0x7ffff7fd4140 "Compilation events (10 events):\n", len=32) at
> /shared/projects/openjdk/jdk-jdk/source/src/hotspot/share/utilities/ostream.cpp:838
> #15 0x00007ffff5f56035 in
> outputStream::do_vsnprintf_and_write_with_automatic_buffer
> (this=0x7ffff0000930, format=0x7ffff64a32e5 "%s (%d events):",
> ap=0x7ffff7fd4978, add_cr=true) at
> /shared/projects/openjdk/jdk-jdk/source/src/hotspot/share/utilities/ostream.cpp:127
> #16 0x00007ffff5f56112 in outputStream::do_vsnprintf_and_write
> (this=0x7ffff0000930, format=0x7ffff64a32e5 "%s (%d events):",
> ap=0x7ffff7fd4978, add_cr=true) at
> /shared/projects/openjdk/jdk-jdk/source/src/hotspot/share/utilities/ostream.cpp:140
> #17 0x00007ffff5f5626a in outputStream::print_cr (this=0x7ffff0000930,
> format=0x7ffff64a32e5 "%s (%d events):") at
> /shared/projects/openjdk/jdk-jdk/source/src/hotspot/share/utilities/ostream.cpp:154
> #18 0x00007ffff576b507 in EventLogBase<StringLogMessage>::print_log_impl
> (this=0x7ffff02b51b0, out=0x7ffff0000930) at
> /shared/projects/openjdk/jdk-jdk/source/src/hotspot/share/utilities/events.hpp:263
> #19 0x00007ffff576b4bb in EventLogBase<StringLogMessage>::print_log_on
> (this=0x7ffff02b51b0, out=0x7ffff0000930) at
> /shared/projects/openjdk/jdk-jdk/source/src/hotspot/share/utilities/events.hpp:256
> #20 0x00007ffff590334a in Events::print_all (out=0x7ffff0000930) at
> /shared/projects/openjdk/jdk-jdk/source/src/hotspot/share/utilities/events.cpp:56
> #21 0x00007ffff5abcb50 in print_statistics () at
> /shared/projects/openjdk/jdk-jdk/source/src/hotspot/share/runtime/java.cpp:361
> 
> Is this by design?
> 
> I would have thought that tty is one of the low level things which I would
> always expect work, since it is often used for debug output.
> 
> Thank you,
> 
> Thomas
>