RFR: 8148630: Convert TraceStartupTime to Unified Logging

[David Holmes]

On 17/02/2016 11:37 AM, Kim Barrett wrote:
>> On Feb 15, 2016, at 8:13 PM, Kim Barrett <kim.barrett at oracle.com> 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.
>
> I think even better is to follow up on Marcus's excellent suggestion
> of using a function pointer, leading to something like this:
>
> Add a format function pointer member to TraceTime, rather than a
> LogTagType, similar to the one in logStream, e.g.
>
>    void (*_log_func)(const char* fmt, ...) ATTRIBUTE_PRINTF(1, 2);
>
> If not supplied by constructor, default to a special helper function
> (see tty_trace below). Also don't need new getStream function.
>
> static void tty_trace(const char* fmt, ...) {
>    va_list args;
>    va_start(args, fmt);
>    tty->vprint_cr(vmt, args);
>    tty->flush();
>    va_end(args);
> }
>
> TraceTime::~TraceTime() {
>    ...
>    if (_verbose) {
>      // kab: _log_func is either tty_trace or LogHandle(...)::write<level>
>      _log_func("%s, %3.7f secs", _title, _t.seconds());
>    }
> }
>
> Using:
>
>    TraceTime timer("Initialize java.lang classes",
>                    log_is_enabled(Info, startuptime),
> 		  LogHandle(startuptime)::write<LogLevel::Info>);
>
> The LogHandle expression can be packaged up so one just writes
> something like
>
>    LogWriter(Info, startuptime)
>
> e.g.
>
> #define LogWriter(level, ...) (LogHandle(__VA_ARGS__)::write<LogLevel::level>)
>
> and for usage we have
>
>    TraceTime timer("Initialize java.lang classes",
>                    log_is_enabled(Info, startuptime),
> 		  LogWriter(Info, startuptime));
>

I've added the above to JDK-8150015. However I would much prefer that we 
can write simply:

TraceTime timer (<msg>, <log-tag>, <log-level>);

and internalize the log_is_enabled and LogWriter functionality.

Cheers,
David