RFR: 8150083: Convert VerboseVerification to Unified Logging

[David Holmes]

Hi Rachel,

On 8/03/2016 6:18 AM, Rachel Protacio wrote:
> 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

All good. The duplication situation is not completely clean but I don't 
see any general way to handle it given the need to extract different 
streams depending on the log tag that is active.

Thanks,
David

> 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
>