RFR: 8150083: Convert VerboseVerification to Unified Logging

[Rachel Protacio]

Hi,

On 3/7/2016 4:27 PM, David Holmes wrote:
> 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.
>
Thank you, David. Will commit.
Rachel
> 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
>>