RFR: 8143157: Convert TraceVMOperation to Unified Logging
Coleen Phillimore
coleen.phillimore at oracle.com
Thu Nov 19 15:27:45 UTC 2015
On 11/18/15 5:06 PM, 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.
>
>> 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.)
Something like what both you and Rachel said?
outputStream* debugstream;
if (log_is_enabled(Debug, vmoperations)) {
debugstream = LogHandle(vmoperation)::debug_stream();
log output
enabled = true;
}
vm_operation
if (enabled) {
log output again
}
>
>>> 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.
I think the only locking is the tty which the GC uses so if it's not
safe for safepoint use, then there's another bigger problem with the
framework.
>
>>>>
>>>> ---
>>>>
>>>> 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.
Either way! The '[' on the first line and the ']' on the second log
line match up but we could drop both or keep them. This doesn't look
like a big deal! "start" and "end" are too noisy.
>
>>>>
>>>> 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 ???
>
> 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.
We picked debug level. It seems like debug level. Do you think it
should be Info level? Is it important information?
>
>>>> 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.
>
Yes, we do intend on making this assessment and argument for each
logging level because we don't want a simple flat logging system. The
code that we are logging isn't simple nor flat. I can cut/paste the
decision graph for you again.
Thanks,
Coleen
> Thanks,
> David
>
>> Thanks,
>> Rachel
>>>>
>>>>
>>>> Thanks,
>>>> David
>>>>
>>>>> Thank you very much,
>>>>> Rachel
>>>
>>
More information about the hotspot-runtime-dev
mailing list