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

Wed Feb 24 17:51:42 UTC 2016

p.s. I tested my change on Linux, Aix, MacOS and Windows, but was unable to
test on Solaris - I have some unrelated build errors I still have not
figured out. VM seems to build though.

Kind Regards, Thomas

On Wed, Feb 24, 2016 at 6:47 PM, Thomas Stüfe <thomas.stuefe at gmail.com>
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/
>
> 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>
> 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
>>>
>>> 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.
>
>
>>
>>> 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>
>>> 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/
>>>>>
>>>>>
>>>> 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
>>>>>
>>>>>
>>>>
>>>>
>