RFR: 8143157: Convert TraceVMOperation to Unified Logging

[Max Ockner]

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("]");
     }
   }

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