RFR: 8148630: Convert TraceStartupTime to Unified Logging

Rachel Protacio rachel.protacio at oracle.com
Wed Feb 17 16:06:21 UTC 2016 

On 2/15/2016 11:31 PM, David Holmes wrote:
> 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.
Thanks for catching. Removed it and it builds fine.

Will respond to the rest of the discussion in the most recent emails.
R
>
>> 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
>>>>>
>>>>
>>

More information about the hotspot-runtime-dev mailing list