Hi all,
thanks a lot for all the input! I have prepared a new version of the webrev
incorporating the suggestions you made (at least I tried):
http://cr.openjdk.java.net/~ghaug/webrevs/8200720.v3/
This version outputs the thread times unconditionally while the other
information is guarded by a flags. I think, most participants found the thread
times the most valuable information and had no (strong) objections to adding
them unconditionally.
@David
Implementation is much simpler with conditional output only for JavaThreads. I
could get rid of the terrible hack (changing the flag) without having to change
too many source files.
The information on allocated bytes is present in the Thread class already
before this proposed change, I just print it. It might be sensible to move
_allocated_bytes and the respective methods to the ThreadStatisticInfo class as
Götz suggested. I haven’t done that in the current version, though.
@David and Thomas
I've removed the pthread-id output. I'm unsure myself what it could be good
for. Anyway, we could add it with a separate change (with a better
implementation) if there is a need to.
@Chris
As you have written, the user has no direct contact to the attach listener of
the VM and jstack won't misinterpret e.g. -help. I agree that the parsing in
attachListener.cpp could be more robust. However, it hasn't been so far either.
All that is done in the current implementation is a strcmp to -l everything
else will be silently ignored. I can try to make this more robust or we could
say that the new output is only available via jcmd. OTH nothing bad can happen
with the current version of the proposed change, so we could also leave it as
it is. What would you prefer?
@Kirk and Thomas
Implementing a new diagnostic command is certainly well worth a thought.
However, it appears to me that it's not necessary in this case. There are
already flags to jstack and jcmd Thread.print, so it's not that uncommon. The
amount of information that would be available by a new diagnostic command and
that is now added to the thread dump is quite small and I think that is
tolerable. Moreover, and most importantly, our support team is use to find the
information in the thread dump and it would make things easier to us if I could
leave it there.
Thanks again and have a nice weekend,
Gunter
On 06.06.18, 04:56, "David Holmes" <david.hol...@oracle.com> wrote:
Hi Goetz,
On 5/06/2018 11:07 PM, Lindenmaier, Goetz wrote:
> Hi
>
> this discussion touched a lot of points so far, which seem
> to lead to different conclusions.
>
> I think we should look at the values printed:
>
> 1. cpu=6300.65ms elapsed=123.28s
> Overhead
> cpu time:
> * system calls at thread dump time
> elapsed time:
> * 1 system call at thread creation time
> * 1 64-bit field per thread for the thread start time
> * 1 system call at thread dump time
>
> As I understand, JDK-8143176 would have had to get the
> time at each locking, which is much more time critical
> than doing this during thread creation. While
Correct.
> the time a lock was held would be much more useful,
> the ratio here, combined with knowledge about the application,
> could lead to the conclusion that the thread is wrongly
> blocked at much lower cost.
Agreed. I see no issue with unconditionally adding this information as
it should address some of the concerns of 8143176 as well.
>
> 2. pthread-id=0x109708000
> Overhead:
> * a field access at thread dump time. Negligible I would say.
I'd overlooked this addition, but it is of course the chunk of ifdef
code in osThread.cpp that I objected to. The problem I have here is the
convoluted mess of "thread identifiers" that we already have. We
currently print:
st->print("tid=" INTPTR_FORMAT " ", p2i(this));
which is just the address of the Thread/JavaThread object. Then:
st->print("nid=0x%x ", thread_id());
where 'n' is supposed to represent "native thread id", which is:
- linux: kernel thread id from syscall gettid
- solaris: thread library identity from thr_create() or thr_self()
- windows: thread id from _beginthreadex
- OS X: kernel thread id from pthread_mach_thread_np(pthread_self());
- Other BSD: kernel (?) thread id from syscall thr_self or getthrid
- AIX: thread library identity from pthread_create() or pthread_self()
It's telling that the code Gunter added gets the thread library id on
linux, but a "kernel thread id" on other platforms! Do we want to see a
thread library id and a kernel thread id? IIRC nid is supposed be the id
you need to see the thread in a debugger. In which case I'm unclear what
role the thread id Gunter wants to add is playing? I don't think we need
to see kernel ids in general, and pthread-id isn't useful for debugging
is it?
>
> 3. allocated=242236760B defined_classes=1725
> Overhead:
> * 1 64-bit field per thread.
> * counter increment on class creation
>
> Especially defined_classes seems to be controversial.
> As this only makes sense for Java threads, this could
> be printed in a line of it's own in Threads::print_on_error()
> (which already gets a flag to customize for jstack:
> print_concurrent_locks) by calling a dedicated function in Thread.
> No need for flag PrintExtendedThreadInfo thus.
>
> But I would propose to drop this information as it is
> too controversial.
Agreed.
> This leaves the times and the pthread-id to be decided whether
> they are worth the cost. If so, I think they should be printed
> unconditional.
Agreed. With some refinement of the "thread id" issue.
> If a flag is required to avoid bloating the info in the default case,
> I would include more infos, as os_prio and nid under that flag.
Of course those things exist for good reason. The native id is supposed
to be what aids in you matching what you see in our thread dumps with
what you see in a debugger. Priority is less of an issue these days, but
there was a time ... ;-)
> As jstack is deprecated, changes to jstack could be skipped always
> disabling the new printouts.
>
> Finally, I would propose to move _allocated_bytes into
> threadStatisticInfo.hpp.
Didn't that part get dropped? (You don't need it for the time info or
thread id). That's a GC logging issue to me.
Thanks,
David
> Best regards,
> Goetz.
>
>
>
>
>> -----Original Message-----
>> From: serviceability-dev [mailto:serviceability-dev-
>> boun...@openjdk.java.net] On Behalf Of David Holmes
>> Sent: Dienstag, 5. Juni 2018 04:53
>> To: Haug, Gunter <gunter.h...@sap.com>; Chris Plummer
>> <chris.plum...@oracle.com>; serviceability-dev <serviceability-
>> d...@openjdk.java.net>; Langer, Christoph <christoph.lan...@sap.com>;
>> hotspot-runtime-...@openjdk.java.net
>> Subject: Re: RFR(S): 8200720: Print additional information in thread
dump
>> (times, allocated bytes etc.)
>>
>> Hi Gunter,
>>
>> On 5/06/2018 1:27 AM, Haug, Gunter wrote:
>>> Hi David, Chris,
>>>
>>> would it be an option to unconditionally print the additional
information?
>> Regardless which way this is implemented it will be rather complicated
and it
>> only switches on/off a few field in the thread dump.
>>
>> I'm not convinced this is all suitable information for a thread stack
>> dump. I can see the time information being useful if using the dump to
>> try and diagnoze a hang or responsiveness issue. But the allocated-bytes
>> and classes-defined just doesn't seem useful in the context of a thread
>> dump to me. Anyone interested in allocation stats is going to be looking
>> at GC logs etc which is where this belongs. Ditto the class-stats belong
>> in some kind of classloading logging IMHO.
>>
>> I'm very reluctant to burden the implementation with capturing these
>> kinds of stats, just to use for diagnostic purposes that may not even be
>> asked for. I'm very much in the "you shouldn't pay for what you don't
>> use" camp in that regard. (See my comments in JDK-8143176 referenced by
>> Sean.)
>>
>> The ThreadStatisticInfo adds overhead to every thread object - and I'd
>> have to suspect there could be overlap with whatever flight recorder
>> sticks in there too. (Thread has become even more bloated in recent
time!).
>>
>> Cheers,
>> David
>>
>>
>>> Thanks,
>>> Gunter
>>>
>>> On 04.06.18, 01:13, "David Holmes" <david.hol...@oracle.com> wrote:
>>>
>>> Hi Gunter, Chris,
>>>
>>> Sorry just trying to catch up and this is only a partial look so
far ...
>>>
>>> BTW these changes are not limited to serviceability code so
adding in
>>> runtime team as well.
>>>
>>> On 2/06/2018 9:12 AM, Chris Plummer wrote:
>>> > Hi Gunter,
>>> >
>>> > On 6/1/18 3:17 AM, Haug, Gunter wrote:
>>> >> Hi Chris,
>>> >>
>>> >> thanks for looking into this!
>>> >>
>>> >> Re the synchronization: The value is stored only in a VM
operation at
>>> >> a safepoint by the VM thread. I was of the opinion, that this
could
>>> >> not be interrupted by a second VM operation (of the same
type). Or
>> am
>>> >> I missing something else?
>>> > I was really thinking more about the temporary changing of
>>> > PrintExtendedThreadInfo, not the value stored in the VMOp. You
may
>> be be
>>> > correct that no more than one VMOp is executing, but while it
is
>>> > executing it is has changed the value of
PrintExtendedThreadInfo,
>> which
>>> > might have an impact on anything else that triggers printing
thread info
>>> > while the VMOp is executing.
>>>
>>> Even if nothing else can possibly be running during the
safepoint I find
>>> it extremely bad form to change a command-line flag in this way,
>>> particularly from a safepoint!
>>>
>>> If this flag is intended to be dynamically enabled as part of a
dcmd
>>> then it should also be a Manageable flag IMHO.
>>>
>>> That said ...
>>>
>>> >> I did think about passing an argument to the various
print_on
>> member
>>> >> functions of the thread classes, but this would require rather
>>> >> extensive code changes for a rather tiny extension. Therefore
I feel
>>> >> doing it like this is the lesser evil.
>>>
>>> ... it's obviously not truly a global setting, but one that is
needed on
>>> a per-print-request basis. The flag is just the default, but if
the
>>> default is off you still want to enable extended printing on a
>>> per-request basis.
>>>
>>> The current print_on mechanics is not set up for this kind of
>>> flexibility. I think this needs more thought.
>>>
>>> ---
>>>
>>> Re osThread.cpp shared code changes ... I really hate to see all
the
>>> ifdefs in there. Please add a pd_print_on function to support
this if
>>> you truly want platform specific information.
>>>
>>> ---
>>>
>>> threadStatisticInfo.hpp
>>>
>>> typo: getElepsedTime() -> getElapsedTime()
>>>
>>> Thanks,
>>> David
>>>
>>>
>>>
>>> >>
>>> >> Re thread_dump(): I think it's correct or, well, at least it
works ;-)
>>> >> In fact jstack will transfer the "-e" and "-l" in only one
string,
>>> >> i.e. op->arg(0).
>>> > So you are saying that op->arg(0) is "-e -l" when using
jstack? I think
>>> > you really need to clean up the parsing. As it stands right
now passing,
>>> > I get the feeling that if a user erroneously asks for help by
using
>>> > "jcmd <pid> Thread.Print -help", it will end up executing with
-e an -l
>>> > enabled, and no failure for the invalid "-help" option.
>>> >> Christoph has already explained my reasoning. But I agree,
it's not
>>> >> nice and I would be happy to do it like Christoph suggested.
>>> > I'll respond separately to his suggestion.
>>> >
>>> > thanks,
>>> >
>>> > Chris
>>> >>
>>> >> And typo fixed, sorry.
>>> >>
>>> >> Thanks again,
>>> >> Gunter
>>> >>
>>> >> On 01.06.18, 00:03, "Chris Plummer" <chris.plum...@oracle.com>
>> wrote:
>>> >>
>>> >> 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
>>> >> > >
>>> >> > >
>>> >> >
>>> >> >
>>> >> >
>>> >> >
>>> >> >
>>> >>
>>> >
>>> >
>>>
>>>
