RFR: 8148630: Convert TraceStartupTime to Unified Logging

[David Holmes]

On 16/02/2016 8:39 AM, Rachel Protacio wrote:
> Hi,
>
> New changeset: http://cr.openjdk.java.net/~rprotacio/8148630.01/

src/share/vm/runtime/timer.hpp

+ class outpuStream;

Typo - so forward declaration is apparently not needed.

> See comments below.
>
> On 2/15/2016 2:10 AM, David Holmes wrote:
>> On 13/02/2016 12:21 AM, Coleen Phillimore wrote:
>>>
>>> Hi Rachel, I think this looks like a good approach to minimize the
>>> intrusion of the timing code, ie. not adding resource marks and streams
>>> around TraceTime constructor.
>>>
>>> Maybe David's concern is that there are multiple instances of this sort
>>> of thing.
>>>
>>> *-TraceTime timer("StubRoutines generation 1",TraceStartupTime);*
>>> *+ log_is_enabled(Info, startuptime),*
>>> *+ LogTag::_startuptime);*
>>
>> That was my first observation - looks very verbose and repetitive.
>>
>> 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.

As I said a couple of times already I had expected you to dispense with 
the convenience macros and use the "raw" UL API instead. Having looked 
at that it is unclear, due to all template-plus-varargs-magic, exactly 
how this might be achieved. But I can't see why runtime level and tag 
variables should be a problem. I think the API to do what I've suggested 
is buried in the UL framework somewhere, we might just need help from a 
UL expert in digging it out.

> 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.

We'll have to agree to disagree.

Thanks,
David

>
> 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");
>
>> Thanks,
>> David
>>
>>> Also, the new output is tons better.  Why is there a newline after this
>>> in both cases?
>>>
>>>     [0.217s][info][startuptime] MethodHandles adapters generation,
>>>     0.0002843 secs
>>>
>>> I don't see it in the code.
>>>
>>> Thanks,
>>> Coleen
>>>
> That happened in the email somehow. The actual output does not contain a
> newline.
>
> Thanks,
> Rachel
>>> On 2/11/16 10:55 AM, Rachel Protacio wrote:
>>>> Hi,
>>>>
>>>> On 2/11/2016 1:45 AM, David Holmes wrote:
>>>>> Looking in some more detail ...
>>>>>
>>>>> On 11/02/2016 7:46 AM, Rachel Protacio wrote:
>>>>>> Hello,
>>>>>>
>>>>>> Please review this fix for
>>>>>> https://bugs.openjdk.java.net/browse/JDK-8148630, converting
>>>>>> -XX:+TraceStartupTime to -Xlog:startuptime, with the old option
>>>>>> aliased
>>>>>> to the new logging one since it is product-level.
>>>>>
>>>>> It is a develop flag, not product. But I don't see the aliasing in
>>>>> the webrev anyway.
>>>> Sorry about that, you're absolutely right. I got confused in writing
>>>> the email because of the other change I'm working on right now.
>>>>>
>>>>> Looking at the TraceTime destructor:
>>>>>
>>>>>        switch (_tag) {
>>>>>          case LogTag::_startuptime :
>>>>>            log_info(startuptime)("%s, %3.7f secs", _title,
>>>>> _t.seconds());
>>>>>            break;
>>>>>          case LogTag::__NO_TAG :
>>>>>          default :
>>>>>            tty->print_cr("[%s, %3.7f secs]", _title, _t.seconds());
>>>>>            tty->flush();
>>>>>        }
>>>>>
>>>>> TraceTime should not have a hard-wired set of LogTag values, nor
>>>>> should it know the log-level associated with any tags. That
>>>>> information should all be stored in the TraceTime instance when
>>>>> constructed and the logging performed in a generic way based on the
>>>>> stored level and tag.
>>>> So there are two problems here. First, because the log_<level>
>>>> functions are macros, you can't just set a variable "tag =
>>>> LogTag::_startuptime" and then do
>>>>     log_info(tag)(...)
>>>> because the compiler will complain that "tag" is not a valid tag.
>>>>
>>>> The second approach would be to pass in the logging stream to the
>>>> constructor, and then print to that stream, but because the stream
>>>> requires a ResourceMark, I was unable to find a successful way to do
>>>> that. I tried declaring the ResourceMark before the code that
>>>> initializes the TraceTime object, but if it is scoped within a
>>>> log_is_enabled conditional, i.e.
>>>>
>>>>    if (log_is_enabled(startuptime)) {
>>>>         ResourceMark rm;
>>>>         TraceTime timer("Interpreter generation", log_is_enabled(Info,
>>>>    startuptime), LogTag::_startuptime);
>>>>    }
>>>>
>>>> then the ResourceMark removes the stream before the destructor is
>>>> called. And if it is not scoped, i.e. just
>>>>
>>>>    ResourceMark rm;
>>>>    TraceTime timer("Interpreter generation", log_is_enabled(Info,
>>>>    startuptime), LogTag::_startuptime);
>>>>
>>>> then it messes up the rest of the functions between the TraceTime
>>>> construction and the destruction.
>>>>
>>>> And I was unable to find a way to create a ResourceMark within the
>>>> TraceTime object itself - it would not compile if it was made a member
>>>> of the class, I think what was happening is that it would try to make
>>>> it when loading the .hpp file, but there was no THREAD at that time.
>>>> And if it's not in the .hpp file, then it's not stored in the
>>>> instance. So I agree that it would be better with one of these
>>>> approaches, but there doesn't seem to be a way to do it.
>>>>
>>>> Rachel
>>>>>
>>>>> Thanks,
>>>>> David
>>>>> -----
>>>>>
>>>>>> Open webrev: http://cr.openjdk.java.net/~rprotacio/8148630/
>>>>>>
>>>>>> Contains new jtreg test, and tested using JPRT. Currently running RBT
>>>>>> quick and non-colo tests to verify embedded/ARM (testing delayed
>>>>>> because
>>>>>> of RBT's being down); I'll reply with an update if they don't pass.
>>>>>>
>>>>>> Note that in memory/metaspaceShared.cpp, I've added curly brackets
>>>>>> around the MetaspaceShared::preload_and_dump(TRAPS) code before
>>>>>> exit(0)
>>>>>> is called because Dmitry noticed that without it, the timer's
>>>>>> destructor
>>>>>> was not in fact being called, so it wouldn't print out the info.
>>>>>>
>>>>>> Also, note that I have altered the printing scheme for the TraceTime
>>>>>> objects, so that they print the title and time all at once. In the
>>>>>> original code, there was often interleaving and therefore potentially
>>>>>> misleading output because the title was printed at initialization,
>>>>>> and
>>>>>> the time printed at destruction. There was no guarantee of order or
>>>>>> correlation in the printed output.
>>>>>>
>>>>>> Original output:
>>>>>>
>>>>>>     $ java -XX:+TraceStartupTime -version
>>>>>>     [Create VM[StubRoutines generation 1, 0.0020992 secs]
>>>>>>     [Genesis, 0.0707006 secs]
>>>>>>     [TemplateTable initialization, 0.0000252 secs]
>>>>>>     [Interpreter generation, 0.0078040 secs]
>>>>>>     [StubRoutines generation 2, 0.0016265 secs]
>>>>>>     [Start VMThread, 0.0003409 secs]
>>>>>>     [Initialize java.lang classes, 0.1160241 secs]
>>>>>>     [MethodHandles adapters generation, 0.0003382 secs]
>>>>>>     , 0.3457703 secs]
>>>>>>     java version "9-internal"
>>>>>>     Java(TM) SE Runtime Environment (fastdebug build
>>>>>>     9-internal+0-2016-02-03-174035.rprotaci.clean)
>>>>>>     Java HotSpot(TM) 64-Bit Server VM (fastdebug build
>>>>>>     9-internal+0-2016-02-03-174035.rprotaci.clean, mixed mode)
>>>>>>
>>>>>> New output:
>>>>>>
>>>>>>     $ java -Xlog:startuptime -version
>>>>>>     [0.017s][info][startuptime] StubRoutines generation 1, 0.0008210
>>>>>> secs
>>>>>>     [0.078s][info][startuptime] Genesis, 0.0614780 secs
>>>>>>     [0.078s][info][startuptime] TemplateTable initialization,
>>>>>> 0.0000223
>>>>>> secs
>>>>>>     [0.084s][info][startuptime] Interpreter generation, 0.0054339
>>>>>> secs
>>>>>>     [0.131s][info][startuptime] StubRoutines generation 2, 0.0015735
>>>>>> secs
>>>>>>     [0.132s][info][startuptime] Start VMThread, 0.0003322 secs
>>>>>>     [0.189s][info][startuptime] Initialize java.lang classes,
>>>>>> 0.0568726
>>>>>> secs
>>>>>>     [0.217s][info][startuptime] MethodHandles adapters generation,
>>>>>>     0.0002843 secs
>>>>>>     [0.218s][info][startuptime] Create VM, 0.2115240 secs
>>>>>>     java version "9-internal"
>>>>>>     Java(TM) SE Runtime Environment (fastdebug build
>>>>>>     9-internal+0-2016-02-01-141226.rprotaci.8148630)
>>>>>>     Java HotSpot(TM) 64-Bit Server VM (fastdebug build
>>>>>>     9-internal+0-2016-02-01-141226.rprotaci.8148630, mixed mode)
>>>>>>
>>>>>> So the new output for non-TraceStartupTime options looks the same as
>>>>>> before, but all the printing is done during destruction.
>>>>>>
>>>>>> Thank you,
>>>>>> Rachel
>>>>
>>>
>