RFR: 8143157: Convert TraceVMOperation to Unified Logging (original) (raw)

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 logisenabled 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 VMOperation::evaluate() { ResourceMark rm; ! bool enabled = false; ! if (logisenabled(Debug, vmoperation)) { ! outputStream* debugstream = LogHandle(vmoperation)::debugstream(); ! enabled = true; ! if (enabled) { ! printonerror(debugstream); ! debugstream->cr(); } doit(); ! if (enabled) { ! printonerror(debugstream); ! debugstream->printcr("]"); } } 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 (logisenabled(Debug, vmoperation)) { debugstream = LogHandle(vmoperation)::debugstream(); You may run afoul of the static analyzer when you use debugstream in the logging clause after the doit(). It won't know that logisenabled 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 logisenabled() 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 logisenabled twice is worse than adding a boolean check and cluttering the code and making it less readable. The argument for changing logisenabled() 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 logisenabled 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/vmoperations.cpp void VMOperation::evaluate() { ResourceMark rm; ! outputStream* debugstream = LogHandle(vmoperation)::debugstream(); ! if (logisenabled(Debug, vmoperation)) { ! debugstream->print("["); ! printonerror(debugstream); ! debugstream->cr(); } doit(); ! if (logisenabled(Debug, vmoperation)) { ! printonerror(debugstream); ! debugstream->printcr("]"); } } Why are you calling printonerror 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 "[" 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: [VMOperation (0x00007fa3b44ce700): G1CollectFull, mode: safepoint, requested by thread 0x00007fa3ac018000 <code from doit() and not from TraceVMOperation> ] becomes [0.257s][debug ][vmoperation] [VMOperation (0x00007f74e589c700): G1CollectFull, mode: safepoint, requested by thread 0x00007f74dc018000 <code from doit() and not from TraceVMOperation> [0.272s][debug ][vmoperation] VMOperation (0x00007f74e589c700): G1CollectFull, mode: safepoint, requested by thread 0x00007f74dc018000] rather than [0.257s][debug ][vmoperation] [VMOperation (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 "=" 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. 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)::debugstream(); always gets executed - and we evaluate isenabled 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. 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