RFR: 8148630: Convert TraceStartupTime to Unified Logging
Marcus Larsson
marcus.larsson at oracle.com
Wed Feb 17 09:47:43 UTC 2016
On 02/17/2016 02:39 AM, David Holmes wrote:
> I have filed:
>
> https://bugs.openjdk.java.net/browse/JDK-8150015
>
> "Integrate TraceTime with Unified Logging more seamlessly"
>
> I have targeted it to JDK 9, so we need someone to pick this up very
> soon.
>
> Thanks,
> David
>
> On 17/02/2016 7:20 AM, David Holmes wrote:
>> On 17/02/2016 5:20 AM, Coleen Phillimore wrote:
>>> 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
>>
>> I don't really follow this given what is currently proposed already has:
>>
>> LogTagType _tag; // stream to print to
>>
>> as a "variable" ??
That variable is used in a switch-case mapping it to a constant
expression. It works fine for a single tag like this, but all supported
tags need to be hard coded in the switch-case. And with tag combinations
it breaks pretty badly.
>>
>>>> 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.
>>
>> Agreed. But the typo I pointed out still needed fixing.
Sounds good!
Thanks,
Marcus
>>
>> David
>> -----
>>
>>> 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