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

[Chris Plummer]

Hi Christoph,

I'm just starting to realize something here. We have both the 
Thread.print dcmd and the threaddump attach command. They both use the 
same underlying VM_PrintThreads op, but both process arguments 
independently. I've been thinking I was looking at dcmd options parsing, 
but it is attach command options parsing that you are changing. So my 
previous comment about a possible errant "-help" option is not realistic 
since jstack would never send that, and when used from a jcmd the proper 
options parsing is done and the jcmd would properly fail (although I'm 
beginning to learn that it gives no useful info as to why the command 
failed).

But that being said, it still should be cleaned up. I think basically 
you need to tokenize arg(0) and look for "-l" and "-e" and reject 
anything else that is not currently supported.

thanks,

Chris

On 6/1/18 3:12 AM, Langer, Christoph wrote:
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-
boun...@openjdk.java.net] On Behalf Of Chris Plummer
Sent: Freitag, 1. Juni 2018 00:04
To: Haug, Gunter <gunter.h...@sap.com>; serviceability-dev
<serviceability-dev@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-boun...@openjdk.java.net on behalf of
gunter.h...@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.plum...@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
          >
          >