RFR: 8148630: Convert TraceStartupTime to Unified Logging

Coleen Phillimore coleen.phillimore at oracle.com
Tue Feb 16 03:16:58 UTC 2016

On 2/15/16 8:13 PM, Kim Barrett wrote:
>> On Feb 15, 2016, at 5:39 PM, Rachel Protacio <rachel.protacio at oracle.com> wrote:
>> New changeset: http://cr.openjdk.java.net/~rprotacio/8148630.01/
>> See comments below.
>> On 2/15/2016 2:10 AM, David Holmes wrote:
>>> But my main concern is that TraceTime should not have a hard-wired set of LogTag values, nor should it know the log-level associated with any of those tags. If we store the tag (which we do) and the level, then we should be able to use the full UL API (not necessarily the log_xxx macros) to perform the logging. TraceTime can potentially be used with many different "tracing" options, and it should not need to know about them all.
>>>> Since there are so many of these, maybe instead introduce a wrapper
>>>> class that inherits from TraceTime, like:
>>>> add outputStream* _st; to TraceTime, initialized to tty.
>>>> TraceStartupTime : public TraceTime {
>>>>        TraceStartupTime(char* s) : TraceTime(s, log_is_enabled(etc),
>>>> LogTag::_startuptime) {}
>>>>        ~TraceStartupTime() { ResourceMark rm ; _st =
>>>> logstream(startuptime);  } // this will call the TraceTime destructor next
>>>> };
>>>> If this doesn't work, I think you've found the cleanest change.
>>> A per-tracing-flag subclass just externalizes the hard-wiring of the known tags and levels. :(
>>> This is really about modifying TraceTime to work nicely with UL. TraceStartupTime is simply the first example of the conversion process.
>> I appreciate your concerns; the issue with this structure is that the general idea of what we want is a TraceTime object that will be able to print to x logging tag streams at level y, but the UL framework basically doesn't support that in particular. If you look at the code, the UL functions we're calling are all nested macros (compile-time), but a dynamic non-hard-wired timer as you suggest would require run-time substitution of variables into levels and tags. This would require adding a subsystem into the logging framework, circumventing the macros in existence, etc. But we don't really need x tags and y levels; all we need is a way to print the TraceStartupTime, TraceSafepointCleanupTime, and maybe 2 other options into the logging streams. So a UL framework addition would be unnecessary. Plus, as we have heard many times from various reviewers, the ideal is having all the logging at "info" level whenever possible, and since that's what we want for these timer options anyway, it's not inappropriate to hard-wire it in.
>> Because some sort of conditional statement is the simplest approach to achieve what we need for all the cases we need it, I've left in the switch statement in the TraceTime destructor. I have, however, added a wrapper class TraceStartupTime in the file runtime/logTimer.hpp, where we'll add the wrapper classes for the other timer logging changes as well. This change addresses the verboseness of the function calls to create the timers. As you can see, the calls are now just
>>     TraceStartupTime s("Genesis");
> I think the translation from LogTagType to logStream is happening at
> the wrong place.  Passing the LogTagType down into the TraceTime
> constructor requires the runtime dispatch from tag to log, with a
> hardwired dispatcher that needs to know about all the tag types that
> might be used.  But I think there's a better way.
> Change TraceTime to have an ostream* member and associated constructor
> argument, rather than the proposed LogTagType member and constructor
> argument.  It can be NULL.
> Tracing startup time can be implemented as
>    {
>      ResourceMark rm;
>      outputStream* logst = NULL;
>      if (log_is_enabled(Info, startuptime)) {
>        logst = Log<startuptime>::info_stream();
>      }

There are multiple places for TraceStartupTime and all this extra code 
is intrusive.  I think how Rachel's implemented this is the most direct 
and cleanest.

>      {
>        TraceTime tt(... stream ...);
>        ... ;
>      }
>      if (stream != 0) logst->cr();
>    }
> This can be packaged up into a helper class with template parameters
> for the tags, e.g. LogTraceTime<startuptime>, if there are multiple
> occurrences.
> Note: There really should be a scoped cleanup helper class for dealing
> with logStreams and perhaps outputStream in general, but I didn't find
> one, only code that manually does stuff like the above little dance.
> It also looks like there should be a flush operation, since writing a
> final cr to mean that doesn't DTRT in arbitrary contexts.

Logging has the flush at the end.

> Rather than a NULL disabled stream, a /dev/null class of outputStream
> might simplify things.

More information about the hotspot-runtime-dev mailing list