RFR: 8143157: Convert TraceVMOperation to Unified Logging
David Holmes
david.holmes at oracle.com
Thu Nov 19 22:32:29 UTC 2015
Hi Marcus,
On 19/11/2015 10:23 PM, Marcus Larsson wrote:
> Hi,
>
> On 2015-11-18 23:06, David Holmes wrote:
>> Hi Rachel,
>>
>> On 19/11/2015 4:41 AM, Rachel Protacio wrote:
>>> Hi,
>>>
>>> On 11/18/2015 12:32 PM, Max Ockner wrote:
>>>> I think the issue is that doit() happens regardless of what is being
>>>> logged. I don't think we can reorder the logging statements relative
>>>> to doit(). In that case, we would be forced to split into 2
>>>> conditionals for the logging.
>>>>
>>>> Still I don't think it is necessary to call log_is_enabled twice, and
>>>> I don't think it is necessary to always define the outputStream. If
>>>> this turns out to be a problem, we could flip things around a bit:
>>>>
>>>> void VM_Operation::evaluate() {
>>>> ResourceMark rm;
>>>> ! bool enabled = false;
>>>> ! if (log_is_enabled(Debug, vmoperation)) {
>>>> ! outputStream* debugstream =
>>>> LogHandle(vmoperation)::debug_stream();
>>>> ! enabled = true;
>>>> ! if (enabled) {
>>>> ! print_on_error(debugstream);
>>>> ! debugstream->cr();
>>>> }
>>>> doit();
>>>> ! if (enabled) {
>>>> ! print_on_error(debugstream);
>>>> ! debugstream->print_cr("]");
>>>> }
>>>> }
>>>>
>>> I'm fine with moving the definition into a conditional (but I can't move
>>> the declaration for scope reasons). It will look like this
>>>
>>> outputStream* debugstream;
>>> if (log_is_enabled(Debug, vmoperation)) {
>>> debugstream = LogHandle(vmoperation)::debug_stream();
>>
>> You may run afoul of the static analyzer when you use debugstream in
>> the logging clause after the doit(). It won't know that log_is_enabled
>> has to return the same answer both times. The use of the enabled flag
>> would address that.
>
> The log configuration can change at runtime, so in this case the two
> log_is_enabled() tests might in fact give different answers.
In that case I would argue for the caching of the initial value of the
log setting. While disabling the log at runtime would be racey wrt
existing logging actions, I think a bracketing log action like this
should either be complete or else fully absent, but not just the first
half or second half.
David
------
>>
>>> To be honest, I'm not sure whether evaluating log_is_enabled twice is
>>> worse than adding a boolean check and cluttering the code and making it
>>> less readable. The argument for changing log_is_enabled() to a boolean
>>> could be extrapolated to say that it should be a boolean for every check
>>> for every tag. And that might be a good idea. But I feel like the
>>> problem with it here is that it comes across as confusing to add
>>> "enabled", which only actually needs to be used once. If we want it
>>> changed, maybe we should change the macro? Or put it outside the
>>> function, even, to make it only evaluate once?
>>
>> I would argue that within a function log_is_enabled should only be
>> called once per tag/level combination. I don't see it impeding
>> readability at all - quite the opposite. (The new logging code in the
>> current example, looks worse to me, than the original, from a
>> clutter/readability perspective.)
>>
>>>> There really is nothing quite like typing code into an editor with
>>>> misaligned columns.
>>>> Anyway, the change looks pretty good to me.
>>>> -Max
>>>>
>>>> On 11/18/2015 4:22 AM, David Holmes wrote:
>>>>> Hi Rachel,
>>>>>
>>>>> On 18/11/2015 5:50 AM, Rachel Protacio wrote:
>>>>>> Hi,
>>>>>>
>>>>>> Please review the following small logging enhancement.
>>>>>>
>>>>>> Summary: The former -XX:+TraceVMOperation flag is updated to the
>>>>>> unified
>>>>>> logging framework and is now replaced with -Xlog:vmoperation in
>>>>>> product
>>>>>> mode.
>>>>>>
>>>>>> Open webrev: http://cr.openjdk.java.net/~rprotacio/8143157/
>>>>>> Bug: https://bugs.openjdk.java.net/browse/JDK-8143157
>>>>>> Testing: Passes jtreg, JPRT, RBT quick tests, and refworkload
>>>>>> performance tests.
>>>>>
>>>>> Meta-question: the logging framework is safe to be called when at a
>>>>> safepoint isn't it?
>>> I haven't seen any problems, but I also don't know what would cause it
>>> to be unsafe. I'd appreciate any guidance in figuring it out!
>>
>> The main thing would be locking of course.
>
> Naturally, logging is and should be available for use at any time,
> including during safepoints.
>
>>
>>>>>
>>>>> ---
>>>>>
>>>>> src/share/vm/runtime/vm_operations.cpp
>>>>>
>>>>> void VM_Operation::evaluate() {
>>>>> ResourceMark rm;
>>>>> ! outputStream* debugstream =
>>>>> LogHandle(vmoperation)::debug_stream();
>>>>> ! if (log_is_enabled(Debug, vmoperation)) {
>>>>> ! debugstream->print("[");
>>>>> ! print_on_error(debugstream);
>>>>> ! debugstream->cr();
>>>>> }
>>>>> doit();
>>>>> ! if (log_is_enabled(Debug, vmoperation)) {
>>>>> ! print_on_error(debugstream);
>>>>> ! debugstream->print_cr("]");
>>>>> }
>>>>> }
>>>>>
>>>>> Why are you calling print_on_error twice?
>>> The problem with switching VMOperation to logging is that in the current
>>> system, the output goes straight to tty and so can be concatenated.
>>> However, since the output triggered by the flag needs to be printed in a
>>> log stream (which is not necessarily tty and which has bracketed
>>> decorations), the "[<VM operation info>" portion comes out in that
>>> stream, which could then be broken be other output, making it confusing
>>> to have a closing "]" sitting around later. Coleen and I agreed that it
>>> would improve output readability to be able to match the closing bracket
>>> by restating the VM operation info. In other words:
>>>
>>> [VM_Operation (0x00007fa3b44ce700): G1CollectFull, mode: safepoint,
>>> requested by thread 0x00007fa3ac018000
>>> <code from doit() and not from TraceVMOperation>
>>> ]
>>>
>>> becomes
>>>
>>> [0.257s][debug ][vmoperation] [VM_Operation (0x00007f74e589c700):
>>> G1CollectFull, mode: safepoint, requested by thread
>>> 0x00007f74dc018000
>>> <code from doit() and not from TraceVMOperation>
>>> [0.272s][debug ][vmoperation] VM_Operation (0x00007f74e589c700):
>>> G1CollectFull, mode: safepoint, requested by thread
>>> 0x00007f74dc018000]
>>>
>>> rather than
>>>
>>> [0.257s][debug ][vmoperation] [VM_Operation (0x00007f74e589c700):
>>> G1CollectFull, mode: safepoint, requested by thread
>>> 0x00007f74dc018000
>>> <code from doit() and not from TraceVMOperation>
>>> [0.272s][debug ][vmoperation] ]
>>>
>>> It should be easier for users to parse this.
>>
>> Okay but in that case each part should have the trailing ]
>>
>> Or, perhaps better, given all the other decoration why not just drop
>> the [ ] bracketing altogether? The intent to was capture all output
>> that occurred while the VMOperation was active, but that is now much
>> clearer in the output anyway. Though perhaps a "start" and "end"
>> indicator would aid parsing - especially when nested VMOperations
>> might occur.
>
> I agree. Adding some sort of end message and skipping the brackets
> altogether seems clearer to me.
>
>>
>>>>>
>>>>> Why is the only logging level for this tag the "debug" level? I think
>>>>> I may be missing part of the way UL works here - can you enable
>>>>> logging both by explicit tag (ie vmoperation) and the level (ie
>>>>> debug)?
>>>>>
>>> You enable the logging with "-Xlog:vmoperation=debug". If you leave of
>>> the "=<level>" portion, it is by default parsed as "=info". We don't
>>> believe this vmoperation logging needs to come out by default in the
>>> case where someone asks for "-Xlog:all", so we put it one level below.
>>
>> <sigh> So does -Xlog:all signify all tags at info level or ???
>
> Yes.
>
>>
>> I think this is real conceptual problem with the UL framework. I
>> should be able to define the info/trace/debug levels for a given tag,
>> without having to think about how they interact with a "log all" request.
>
> I believe focus should be on classifying each log message according to
> its component & type (tags) and verbosity & cost (level), and less about
> which users will get it using what command line.
> The log configuration is very flexible to allow users full control over
> the logging they want, all we need to do on the development side is to
> keep the logging logically classified and ordered so that the users can
> easily select from it.
>
> Thanks,
> Marcus
>
>>
>>>>> And I know I sound like a broken record but I'm concerned about the
>>>>> overhead of the logging actions when it is not enabled ie:
>>>>>
>>>>> outputStream* debugstream = LogHandle(vmoperation)::debug_stream();
>>>>>
>>>>> always gets executed - and we evaluate is_enabled twice.
>>>>>
>>> See my reply to Max above.
>>>>> ---
>>>>>
>>>>> test/runtime/logging/VMOperationTestMain.java
>>>>>
>>>>> Can you add a comment explaining what the logic is attempting to do
>>>>> please. I'm curious how many times the loop executes before you get a
>>>>> safepoint-based GC (and how it varies for different GC's).
>>>>>
>>>>> Style nit: while( -> while (
>>> Yes, will fix.
>>>>>
>>>>>> A compatability request has been accepted with regard to this change.
>>>>>
>>>>> I'll record my objections again to the conversion of develop flags to
>>>>> product. <sigh>
>>> Thanks for voicing your concern. The justification for this tag being
>>> product is that it could be useful to helping diagnose user problems, it
>>> does not slow performance when off, and it minimally increases the size
>>> of the code. If any of these prove to be false in aggregated logging
>>> options, we can move it to develop level during code freeze.
>>
>> You could make that argument for every piece of logging and end up
>> with a very simple flat logging system. :) It is all very subjective
>> of course.
>>
>> Thanks,
>> David
>>
>>> Thanks,
>>> Rachel
>>>>>
>>>>>
>>>>> Thanks,
>>>>> David
>>>>>
>>>>>> Thank you very much,
>>>>>> Rachel
>>>>
>>>
>
More information about the hotspot-runtime-dev
mailing list