RFR: 8148630: Convert TraceStartupTime to Unified Logging
Rachel Protacio
rachel.protacio at oracle.com
Wed Feb 17 16:22:25 UTC 2016
Thank you everyone for the discussion. I'm linking the most updated
webrev here: http://cr.openjdk.java.net/~rprotacio/8148630.02/
The only difference from the last one was the removal of the (typo'ed)
forward declaration. But as I believe my only self-declared reviewer so
far has been Coleen, I still need someone else to review/approve/ask for
this-RFE-specific changes that do not apply to David's 8150015
improvement RFE.
Thanks,
Rachel
On 2/17/2016 4:47 AM, Marcus Larsson wrote:
>
>
> 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.
Fair point. This can be addressed in the follow-up RFE. It's safe for
now since it only gets called from within the code, i.e. can't be broken
by the user.
>
>>>
>>>>> 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!
Fixed in this webrev.
Rachel
>
> 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