RFR(s): 8149036: Add UL tracing for thread related events at os level

Wed Feb 24 18:05:03 UTC 2016

This looks quite a bit nicer.   I will test compilation on solaris when 
I sponsor it.

On 2/24/16 12:47 PM, Thomas Stüfe wrote:
> Hi David,
>
> thank you for the review!
>
> New webrev: 
> http://cr.openjdk.java.net/~stuefe/webrevs/8149036-add-tracing-for-thread-events/webrev.03/webrev/ 
> <http://cr.openjdk.java.net/%7Estuefe/webrevs/8149036-add-tracing-for-thread-events/webrev.03/webrev/>
>
> The changes (one of these days I plan to figure out how to print 
> relative webrevs with mercurial queues) are:
>
> - I fixed the issues you found, see comments inline
> - I changed most of the calls from log_debug() to log_info(), because 
> I found that tracing level more fitting
>
>
> On Wed, Feb 24, 2016 at 1:17 PM, David Holmes <david.holmes at oracle.com 
> <mailto:david.holmes at oracle.com>> wrote:
>
>     Hi Thomas,
>
>     Been waiting for the dust to settle :)
>
>
> :)
>
>
>
>     On 24/02/2016 7:24 PM, Thomas Stüfe wrote:
>
>         Coleen, Marcus,
>
>         thank you for reviewing, and @Coleen, thanks for the
>         sponsoring offer!
>
>         Here the latest Webrev:
>         http://cr.openjdk.java.net/~stuefe/webrevs/8149036-add-tracing-for-thread-events/webrev.02/webrev/index.html
>         <http://cr.openjdk.java.net/%7Estuefe/webrevs/8149036-add-tracing-for-thread-events/webrev.02/webrev/index.html>
>
>         As Marcus suggested, I added a new "thread" tag and added the
>         tag to the
>         logging calls.
>
>
>     I have a few comments ...
>
>     src/os/bsd/vm/os_bsd.cpp
>
>
>      786     LogHandle(os, thread) log;
>      787     if (log.is_debug()) {
>
>
> Oh, good catch, and this was actually a bug, because the 
> "log.warning()" was in the "log.is_debug()" condition so the warning 
> would not have been printed unless log level was debug or higher. I 
> fixed this for the affected platforms.
>
>     I think it is preferable to only create the LogHandle inside the
>     if block. Normally we do an "if (is_enabled...())" check first.
>
>      793         log.warning("Failed to start thread - pthread_create
>     failed (%s) for attributes: %s.",
>      794           strerror(errno),
>     os::Posix::describe_pthread_attr(buf, sizeof(buf), &attr));
>
>     pthread_* functions don't set errno they return the error code
>     directly.
>
>
> Oops. Yes, I fixed that.
>
>     Ditto for src/os/linux/vm/os_linux.cpp
>
>     ---
>
>     src/os/solaris/vm/os_solaris.cpp
>
>     Why did you use a different style for the thr_create logging
>     compared to *NIX? The flags can be described similarly to a
>     pthread-attr object.
>
>     Similar comment for os_windows.cpp.
>
>
> Okay, for both platforms I implemented a similar printout as for the 
> Posix platforms. Now we see flags and stacksize on all platforms.
>
>     ---
>
>     src/share/vm/runtime/thread.cpp
>
>     Personally I think plain warning(...) calls should be converted to
>     untagged logging calls - otherwise the warning will likely never
>     be seen and we want these warnings to be quite visible. But the
>     policy is to do what you did.
>
>
> That is a hot topic in our group and usually frowned at, because 
> unexpected warning output (which may or may not matter to the 
> customer) disturbs automated processes parsing this output.

I *thought* all warnings came out by default and the tags were 
decorations.   Currently warning() call will print the warning because 
PrintWarnings defaults to true.  Isn't logging the same?

thanks,
Coleen

>
>         btw, I found the command line a bit confusing:
>
>         If a logging call is tagged with two tags A and B, I would
>         have thought the
>         default behaviour of "-Xlog:A" is to log all calls tagged at
>         least with A,
>         not all calls which are solely tagged with A and nothing else.
>         I could not
>         even think ot a use case for the latter.
>
>
>     The syntax/semantics is somewhat subjective and obviously have to
>     be learned. I like the fact -Xlog:os only turns on things tagged
>     only with "os".
>
>         After some searching, I found that the behaviour I want and I
>         would think
>         makes sense as default is "-Xlog:A*".
>
>
>     -Xlog:help shows
>
>     -Xlog Usage: -Xlog[:[what][:[output][:[decorators][:output-options]]]]
>              where 'what' is a combination of tags and levels on the
>     form tag1[+tag2...][*][=level][,...]
>              Unless wildcard (*) is specified, only log messages
>     tagged with exactly the tags specified will be matched.
>
>         This also means that log lines will be mysteriously
>         disappearing from
>         output if someone adds another tag to that line, unless I
>         always use an
>         asterix? Or am I just slow to understand the command line syntax?
>
>
>     Unfortunately you need to know how the code is tagged to know what
>     log output to ask for. Once we put these in place we're
>     introducing a new set of compatibility constraints that will make
>     it hard to rework the tagging in the future.
>
>
> Well, I think this design decision (if it even was a deliberate 
> decision) is unfortunate. In the end, like Coleen writes, many may 
> decide to skip to not use multiple tags. Which is unfortunate, because 
> the  ability to have multiple tags per command line is quite a cool 
> feature.
>
> I also still fail to see any use case where I would want to log a tag 
> but only those log sites which are not tagged with something different 
> too. Similarly to a keyword based item search - One usually wants all 
> items for a keyword and does not care if the item is tagged with other 
> keywords too.
>
> Thanks,
>
> Thomas
>
>     Thanks,
>     David
>
>
>         Kind Regards, Thomas
>
>
>
>
>
>
>         On Tue, Feb 23, 2016 at 6:52 PM, Marcus Larsson
>         <marcus.larsson at oracle.com <mailto:marcus.larsson at oracle.com>>
>         wrote:
>
>             Hi,
>
>             On 2016-02-22 17:54, Thomas Stüfe wrote:
>
>                 Dear all,
>
>                 please take a look at this proposed addition to UL.
>                 This adds a number of
>                 trace points to thread creation. In detail:
>
>                 - it traces thread creation and thread creation
>                 errors, including pthread
>                 attributes (for Posix platforms)
>                 - it traces stack location and creation/removal of
>                 stack guard pages.
>
>                 This all was first AIX-only tracing, but I converted
>                 this to UL and made
>                 it
>                 available on all platforms.
>
>                 Bug: https://bugs.openjdk.java.net/browse/JDK-8149036
>                 Webrev:
>
>                 http://cr.openjdk.java.net/~stuefe/webrevs/8149036-add-tracing-for-thread-events/webrev.00/webrev/
>                 <http://cr.openjdk.java.net/%7Estuefe/webrevs/8149036-add-tracing-for-thread-events/webrev.00/webrev/>
>
>
>             It might be a good idea to add a 'thread' tag and use that
>             in addition to
>             the os tag for these messages. It would allow easy
>             filtering of these
>             messages for those interested/uninterested. Just 'os'
>             alone is quite a wide
>             area.
>
>             Thanks,
>             Marcus
>
>
>             Note also that I added a helper function,
>             os::errno_name(), which is a very
>
>                 simple replacement for strerror() without its problems
>                 (thread safety,
>                 unwanted localizations...).
>
>                 What do you think?
>
>                 Kind Regards, Thomas
>
>
>
>