RFR(S): 8200720: Print additional information in thread dump (times, allocated bytes etc.)

Fri Jun 1 10:12:40 UTC 2018

Hi Chris,

I think I should chime in about your 3rd point regarding thread dump parameter parsing.

For the SAP JVM we have extended the thread_dump operation a little bit and it has 3 params (3 is the limit for param numbers):

arg(0) is support for the "-l" switch, as you currently find in OpenJDK
arg(1) is a custom string that could be specified to print out a custom tag or headline in front of the thread dump
arg(2) is a flag to toggle printing the thread dump to the target VM's tty (as opposed to the default behavior of printing the thread dump to the operation's output stream).

So I can see that Gunter explicitly wanted to not break this behavior and added some extension just to arg(0). But I agree that it's probably not the nicest and straight forward thing to do.

What if we parse each argument and check whether it contains "-l" or "-e" or even "-le". So we could add extensions like "-tty" for dump to tty and "-t" for tag or something like this? Then for instance arg(0) could look like "-l -e -tty"?

Best regards
Christoph

> -----Original Message-----
> From: serviceability-dev [mailto:serviceability-dev-
> bounces at openjdk.java.net] On Behalf Of Chris Plummer
> Sent: Freitag, 1. Juni 2018 00:04
> To: Haug, Gunter <gunter.haug at sap.com>; serviceability-dev
> <serviceability-dev at openjdk.java.net>
> Subject: Re: RFR(S): 8200720: Print additional information in thread dump
> (times, allocated bytes etc.)
> 
> Hi Gunter,
> 
> globals.hpp: fix typo "informatiuon"
> 
> I worry a little bit about the synchronizing (if that's the right word)
> of PrintExtendedThreadInfo and the dcmd's -e flag. When using -e, you
> are temporarily enabling PrintExtendedThreadInfo if it was false. This
> temporarily changes the behavior of thread dumps, and could impact other
> uses that happen in parallel. Also, could two simultaneous uses of -e
> result in PrintExtendedThreadInfo not getting restored properly?
> 
> thread_dump() doesn't look right. It looks like you are iterating char
> by char over the argument, and expect something like "-el" to be
> specified rather then "-e -l". The loop should be iterating over
> op->arg(i), not op->arg(0)[i].
> 
> The rest of the changes look fine.
> 
> thanks,
> 
> Chris
> 
> 
> On 5/30/18 8:12 AM, Haug, Gunter wrote:
> > Hi all,
> >
> > As Chris proposed, I have made an the extended output switchable. There
> is an VM flag (PrintExtendedThreadInfo), which is false by default.
> Moreover, there is an Option (-e) which can be used with jcmd Thread.print
> as well as with jstack. The -e option essentially sets PrintExtendedThreadInfo
> true just for the respective thread dump.
> >
> > Here is the updated webrev:
> >
> > http://cr.openjdk.java.net/~ghaug/webrevs/8200720.v2
> >
> > (https://bugs.openjdk.java.net/browse/JDK-8200720)
> >
> > Thanks,
> > Gunter
> >
> >
> > On 02.05.18, 17:07, "serviceability-dev on behalf of Haug, Gunter"
> <serviceability-dev-bounces at openjdk.java.net on behalf of
> gunter.haug at sap.com> wrote:
> >
> >      Hi Chris,
> >
> >      Thanks for looking into this.
> >      You're right, there is a little more we have. We have implemented an IO
> tracing mechanism which - rather as a byproduct - keeps track of bytes read
> and written per thread. However, this of course requires changes not only in
> hotspot. We would be happy to contribute this as well, but this is a far bigger
> change and will probably lead to a far bigger discussion. Anyway, with the
> number of bytes read, the number of classes defined doesn't look that
> arbitrary anymore, as one can correlate IO to class loading.
> >
> >      Regarding the verbose option I think that's a good idea!
> >
> >      Thanks again,
> >      Gunter
> >
> >      On 01.05.18, 22:55, "Chris Plummer" <chris.plummer at oracle.com>
> wrote:
> >
> >          Hi Gunter,
> >
> >          The output you are adding is all useful. I think the question is (and
> >          I'd like to see a few people chime in on this for this review) is
> >          whether or not all of it is the appropriate for a thread's stack dump.
> >          For example, defined_classes is on the fringe of what I would call
> >          generally useful info in a stack dump. Sure, there might be that rare
> >          case when you need it, but how often compared to other useful info
> >          maintained on a per thread basis. How many other bits of useful info
> are
> >          not being printed in favor of defined_classes? It seems you have more
> in
> >          the queue. How many? I'm worried about how cluttered the stack
> dumps
> >          will get. Maybe we should add some sort of verbose thread dumping
> >          option. Just a thought.
> >
> >          As for the implementation, overall it looks good, but I can't speak to
> >          whether or not you are doing proper accounting of defined_classes
> and
> >          bytes allocated. You'll need input from someone with more knowledge
> of
> >          those areas. We'll also need to do some testing to make sure tool tests
> >          are not impacted.
> >
> >          thanks,
> >
> >          Chris
> >
> >          On 4/30/18 2:51 AM, Haug, Gunter wrote:
> >          > Hi,
> >          >
> >          > this is an update to an RFR I posted on hotspot-dev, but it is probably
> more suitable to post it here. Can I please have a review and a sponsor for
> the following enhancement:
> >          >
> >          > http://cr.openjdk.java.net/~ghaug/webrevs/8200720.v1
> >          > https://bugs.openjdk.java.net/browse/JDK-8200720
> >          >
> >          > We at SAP have extended the thread dumps (obtained by jstack or
> jcmd) by several fields providing thread specific information. These
> extensions are quite popular with our support team. With some knowledge
> of the architecture of the application, they often allow for quick and simple
> diagnosis of a running system. Therefore we would like to contribute these
> enhancements.
> >          >
> >          > I took a few simple examples here, namely cpu time, elapsed time
> since thread creation, bytes allocated and classes defined by the thread and
> the pthread-id or equivalent on platforms where it makes sense. Provided it
> is known how the application should behave, a misbehaving thread can
> identified easily.
> >          >
> >          > There is no measurable overhead for this enhancement. However, it
> may be a problem that the format of the output is changed. Tools parsing the
> output may have to be changed.
> >          >
> >          > Here is an example of the output generated:
> >          >
> >          > ------------------------------------------------------
> >          >
> >          > "main" #1 prio=5 os_prio=31 cpu=6300.65ms elapsed=123.28s
> allocated=242236760B defined_classes=1725 tid=0x00007fa13a806000
> nid=0x1c03 pthread-id=0x109708000 waiting on condition
> [0x0000000109707000]
> >          >     java.lang.Thread.State: TIMED_WAITING (sleeping)
> >          >     JavaThread state: _thread_blocked
> >          > Thread: 0x00007fa13a806000 [0x1c03] State: _at_safepoint
> _has_called_back 0 _at_poll_safepoint 0
> >          >     JavaThread state: _thread_blocked
> >          > at java.lang.Thread.sleep(java.base/Native Method)
> >          >             ...
> >          > ------------------------------------------------------
> >          >
> >          > As mentioned above, we have a whole bunch of other
> enhancements to the thread dump similar to this one and would be willing to
> contribute them if there is any interest.
> >          >
> >          > Thanks and best regards,
> >          > Gunter
> >          >
> >          >
> >
> >
> >
> >
> >
> 