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();
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?
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!
---
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.
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.
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.
Thanks,
Rachel
Thanks,
David
Thank you very much,
Rachel
