RFR: 8143157: Convert TraceVMOperation to Unified Logging
David Holmes
david.holmes at oracle.com
Wed Nov 18 22:06:41 UTC 2015
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.)
>> 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.
>>>
>>> ---
>>>
>>> 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.
>>>
>>> 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.
>>> 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