RFR: 8148630: Convert TraceStartupTime to Unified Logging
Coleen Phillimore
coleen.phillimore at oracle.com
Tue Feb 16 19:20:01 UTC 2016
On 2/16/16 11:23 AM, Marcus Larsson wrote:
> Hi,
>
> On 02/16/2016 05:31 AM, 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.
>>
>>> 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.
>>
>
> Log tags are template arguments, so they need to be constant
> expressions and not variables. This makes it a bit tricky to do
> something like this. However, I still think there are better ways to
> do this than the current proposal.
>
> I'm leaning towards a solution similar to what Kim suggested, where
> it's not necessary for the timer to have such detailed knowledge of
> the logging framework. You could even avoid the unnecessary buffering
> happening in the streams by using a function pointer directly to the
> appropriate Log::write function, similar to how logStream is
> implemented today. Both of these approaches also allows for tag
> combinations to be used, which is a limitation of the current proposal
> (can only specify a single tag).
So I have a proposal. What Rachel has looks clean in the code (my
opinion), and correctly translates the TraceStartupTime to unified
logging framework. You can file a further RFE to implement this more
general approach within the framework so that combinations of flags and
levels can be used. That way we can make forward progress on the
runtime translation and you can use this flag as an example when the
more general framework approach is available.
Thanks,
Coleen
>
> Regards,
> Marcus
>
>>> 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