RFR: 8150083: Convert VerboseVerification to Unified Logging

[Rachel Protacio]

Hi,

Thanks for the review, David!

New webrev: http://cr.openjdk.java.net/~rprotacio/8150083.02/
Changes:
     - removed unnecessary ResourceMark
     - added "THREAD" as argument to existing ResourceMarks
     - removed -XX:+VerboseVerification legacy test in 
ClassInitializationTest.java

Responses inline.

On 3/6/2016 8:02 PM, David Holmes wrote:
> Hi Rachel,
>
> A few comments ...
>
> On 5/03/2016 7:42 AM, Rachel Protacio wrote:
>> Hello,
>>
>> Please review this conversion of -XX:+VerboseVerification to
>> -Xlog:verboseverification=info.
>>
>> Bug: https://bugs.openjdk.java.net/browse/JDK-8150083
>> Open webrev: http://cr.openjdk.java.net/~rprotacio/8150083.01/
>
>  if (log_is_enabled(Info, classinit)){
>  194     log_end_verification(LogHandle(classinit)::info_stream(), 
> klassName, exception_name, THREAD);
>  195   }
>  196   if (log_is_enabled(Info, verboseverification)){
>  197     ResourceMark rm;
>  198 
> log_end_verification(LogHandle(verboseverification)::info_stream(), 
> klassName, exception_name, THREAD);
>  199   }
>
> No ResourceMark needed at #197 (for same reason it is not needed at 
> #194).
Oh I see. I've removed it.
>
> ---
>
>  603   if (was_recursively_verified()){
>  604     log_info(verboseverification)("Recursive verification 
> detected for: %s", _klass->external_name());
>
>
>
>  605     log_info(classinit)("Recursive verification detected for: %s",
>  606                         _klass->external_name());
>  607   }
>
> When TraceclassInitialization was converted it was suggested that 
> where we had:
>
> if (TraceClassInitialization || VerboseVerification) {
>   // log something ....
>
> and we then got the output printed twice with classinit using UL, that 
> these would be fixed up when VerboseVerification was converted:
>
> http://mail.openjdk.java.net/pipermail/hotspot-runtime-dev/2015-November/016846.html 
>
>
> "When VerboseVerification is converted to UL, the logging statements 
> will be more compact."
Thanks for bringing that up. So actually since that discussion, the 
precedent has been set with classpath and classloader (?) that rather 
than force a UL combination to log lines that were previously coming from
     if (TraceClassInitialization || VerboseVerification) {
would have to be logged as, e.g.
     log_info(classinit, verboseverification)(<msg>)
which would have to be specified on the command line as one of
     (a) -Xlog:classinit+verboseverification
     (b) -Xlog:classinit*
     (c) -Xlog:verboseverification*
which is unfairly complicated to the user. So since there's a precedent 
to have two separate printings and it is simpler for the user, the plan 
is to leave the code as it is in the webrev. But if you have a specific 
objection and preferred approach, I'm happy to consider it.
>
> ---
>
> test/runtime/logging/ClassInitializationTest.java
>
> I think the "Ensure that VerboseVerification still triggers 
> appropriate messages" subtest can be deleted now as we test 
> -Xlog:verboseverification separately. It was only present to ensure 
> the old VerboseVerification flag still functioned after the classinit 
> change.
>
Good point.
Thank you,
Rachel
> ---
>
> Thanks,
> David
> -----
>
>
>> Sample old output:
>>
>>     Verifying class hello with new format
>>     Verifying method hello.<init>()V
>>     StackMapTable: frame_count = 0
>>     table = {
>>       }
>>     bci: @0
>>     flags: { flagThisUninit }
>>     locals: { uninitializedThis }
>>     stack: { }
>>     offset = 0,  opcode = aload_0
>>     bci: @1
>>     flags: { flagThisUninit }
>>     locals: { uninitializedThis }
>>     stack: { uninitializedThis }
>>     offset = 1,  opcode = invokespecial
>>     bci: @4
>>     flags: { }
>>     locals: { 'hello' }
>>     stack: { }
>>     offset = 4,  opcode = return
>>     Verifying method hello.main([Ljava/lang/String;)V
>>
>> Sample new output:
>>
>>     [0.696s][info][verboseverification] Verifying class
>>     VerboseVerificationTest$InternalClass with new format
>>     [0.696s][info][verboseverification] Verifying method
>>     VerboseVerificationTest$InternalClass.<init>()V
>>     [0.696s][info][verboseverification] StackMapTable: frame_count = 0
>>     [0.696s][info][verboseverification] table = {
>>     [0.696s][info][verboseverification]  }
>>     [0.696s][info][verboseverification] bci: @0
>>     [0.696s][info][verboseverification] flags: { flagThisUninit }
>>     [0.696s][info][verboseverification] locals: { uninitializedThis }
>>     [0.696s][info][verboseverification] stack: { }
>>     [0.696s][info][verboseverification] offset = 0,  opcode = aload_0
>>     [0.696s][info][verboseverification] bci: @1
>>     [0.696s][info][verboseverification] flags: { flagThisUninit }
>>     [0.696s][info][verboseverification] locals: { uninitializedThis }
>>     [0.696s][info][verboseverification] stack: { uninitializedThis }
>>     [0.696s][info][verboseverification] offset = 1,  opcode = 
>> invokespecial
>>     [0.696s][info][verboseverification] bci: @4
>>     [0.696s][info][verboseverification] flags: { }
>>     [0.696s][info][verboseverification] locals: {
>>     'VerboseVerificationTest$InternalClass' }
>>     [0.696s][info][verboseverification] stack: { }
>>     [0.696s][info][verboseverification] offset = 4,  opcode = return
>>     [0.696s][info][verboseverification] Verifying method
>> VerboseVerificationTest$InternalClass.main([Ljava/lang/String;)V
>>
>> Tested with JPRT; jck vm, lang, and api/java_lang; and RBT hotspot and
>> non-colo tests.
>>
>> Thank you,
>> Rachel