RFR: 8142976: TraceClassInitialization has been reimplemented with Unified Logging.

[David Holmes]

On 2/12/2015 7:18 AM, Max Ockner wrote:
> New webrev     http://cr.openjdk.java.net/~mockner/ulclassinit06/
>
> I addressed issues pointed out by David. I also moved test/logging ->
> test/runtime/logging.

verifier.cpp:

In-line with similar discussions in other review threads, does 
log_end_verification need to be a member of Verifier, or can it just be 
a file-static function?

Otherwise looks fine.

> I have not yet addressed the way that VerboseVerification is being
> tested in this fix. I don't think its a problem for now. The way
> VerboseVerification fits with the rest of this change is only temporary
> anyway, and once VerboseVerification is converted to UL, this will be
> redone anyway.

Okay.

Thanks,
David

> Max
>
> On 12/1/2015 2:14 AM, David Holmes wrote:
>> Hi Max,
>>
>> On 1/12/2015 8:39 AM, Max Ockner wrote:
>>> Here is a new webrev: http://cr.openjdk.java.net/~mockner/ulclassinit05/
>>
>> src/share/vm/classfile/verifier.cpp
>>
>> Minor nits: here
>>
>> +     st->print_cr(" exception pending %s ",
>> +       PENDING_EXCEPTION->klass()->external_name());
>>
>> the indentation should be
>>
>> +     st->print_cr(" exception pending %s ",
>> + PENDING_EXCEPTION->klass()->external_name());
> OK
>>
>> similarly here:
>>
>> +     log_info(classinit)("Recursive verification detected for: %s",
>> +           _klass->external_name());
>>
>> should be:
>>
>> +     log_info(classinit)("Recursive verification detected for: %s",
>> +                         _klass->external_name());
>>
> OK
>> ---
>>
>> src/share/vm/oops/instanceKlass.cpp
>>
>> Here:
>>
>>       // trace
>>       ResourceMark rm(THREAD);
>>       log_info(classinit)("[Initialized %s without side effects]",
>> this_k->external_name());
>>
>> the ResourceMark is always constructed even if we don't evaluate the
>> external_name() call that needs it. That may have performance
>> implications. Perhaps we need to also use "if (log_is_enabled(Info,
>> classinit))" here?
>>
> OK
>> ---
>>
>> test/logging/ClassInitializationTest.java
>>
>> I understand the intent with testing VerboseVerification, but I'm not
>> sure this is really the right place to do it. And if you do want to do
>> this here then I would think you need to test the combination of it
>> with the new logging enabled.
>>
>>
> So what do you suggest?
>>> 1) The verifier test uses a small snippet to produce verifier errors and
>>> a discussion with Harold made it seem like this was the most direct way
>>> to hit most of the error messages.
>>
>> Ok.
>>
>>> 2) In general I do not know where the best home is for the logging
>>> tests. I think we can have a separate discussion about this if people
>>> find it to be a problem.
>>
>> Yes separate discussion - but I think in many cases you may want the
>> logging tests with the functional tests to avoid duplicated effort. On
>> the other hand I'm not sure we want to duplicate logging expectations
>> inside tests in the first place :)
>>
>> Thanks,
>> David
>>
>>> 3) You caught a bug in my test! I have addressed this issue.
>>> http://cr.openjdk.java.net/~mockner/ulclassinit05/test/logging/ClassInitializationTest.java.html
>>>
>>>
>>>
>>> Thanks,
>>> Max
>>>
>>>
>>>
>>> On 11/25/2015 7:51 PM, David Holmes wrote:
>>>> Hi Max,
>>>>
>>>> On 25/11/2015 7:27 AM, Max Ockner wrote:
>>>>> New webrev @ http://cr.openjdk.java.net/~mockner/ulclassinit02/
>>>>> Fixed everything that I said I would fix below.
>>>>
>>>> As a direct conversion of existing logging info this looks fine. The
>>>> overlap with VerboseVerification will have to be dealt with later.
>>>>
>>>> Not sure about the test strategy here in that creating a class that
>>>> fails verification just to check what is logged seem a bit over the
>>>> top and potentially duplicates verifier testing. I wonder if the
>>>> logging test could not in fact run an existing verifier test with
>>>> logging enabled? Which raises the question of whether logging tests
>>>> like this come under logging, or under the subsystem being logged?
>>>>
>>>> In the test EagerInitialization is a develop-only flag, and
>>>> VerboseVerification is diagnostic. It isn't obvious this is being
>>>> handled by the createJavaProcessBuilder calls.
>>>>
>>>> Thanks,
>>>> David
>>>>
>>>>>
>>>>> On 11/24/2015 3:40 PM, Rachel Protacio wrote:
>>>>>> Hi,
>>>>>>
>>>>>> Looks mostly good, just a few comments:
>>>>>>
>>>>>> verifier.cpp
>>>>>> - at line 118 (the first "Verification for" line), it should just be
>>>>>> "print", not "print_cr".
>>>>> Thanks. Fixed, though I wonder how much it matters.
>>>>>> - between lines 194 and 195, I think you need a ResourceMark for the
>>>>>> LogHandle stream.
>>>>> The ResourceMark is defined already, it just isn't part of the diffs
>>>>> because it was already there.
>>>>>> - in the sections starting at lines 179 and 608, I appreciate that
>>>>>> you
>>>>>> were minimizing the number of lines, but I think it's a bad idea to
>>>>>> have duplicates of the logged strings. Do you think you could define
>>>>>> the strings outside of the logging and pass it to both functions?
>>>>>> Another possible solution would be to make a function to do that with
>>>>>> a signature like
>>>>>>     void log_multiple(bool enabled1, outputStream* st1, bool
>>>>>> enabled2,
>>>>>> outputStream* st2, char* msg);
>>>>>> that could do this in a more formalized manner. A function like this
>>>>>> could be useful for other similar situations as well while we're
>>>>>> converting flags one by one. Or what are your thoughts on that?
>>>>> Two reasons why I don't think we should do that.
>>>>>      (1) We don't want to evaluate format strings unless something is
>>>>> being logged. I guess if you can find a way to avoid doing this while
>>>>> still making the code look nicer then that is OK. I think it would be
>>>>> just as bad to write extra lines of code just to ensure that a short
>>>>> string isn't duplicated.
>>>>>      (2) We do not guarantee that these two messages will always be
>>>>> the
>>>>> same. A conversation I had with Coleen led me to believe we should
>>>>> keep
>>>>> the messages separate.
>>>>>> - I think the reordered nesting makes sense.
>>>>>>
>>>>>> ClassInitializationTest.java
>>>>>> - nit: can you move the ");"s from the process builder lines onto the
>>>>>> lines before them?
>>>>> OK.
>>>>>>
>>>>>> Thanks,
>>>>>> Rachel
>>>>>>
>>>>>> On 11/24/2015 3:09 PM, Max Ockner wrote:
>>>>>>> Hello,
>>>>>>> Please review my new unified logging code:
>>>>>>>
>>>>>>> Bug: https://bugs.openjdk.java.net/browse/JDK-8142976
>>>>>>> http://cr.openjdk.java.net/~mockner/ulclassinit01/src/share/vm/classfile/verifier.cpp.cdiff.html
>>>>>>>
>>>>>>>
>>>>>>>
>>>>>>> Summary: -XX:+TraceClassInitialization logging has been
>>>>>>> reimplemented
>>>>>>> using unified logging under the classinit tag.
>>>>>>>
>>>>>>> In the segment with recursive verification (see verifier.cpp) I
>>>>>>> reordered the nested if statement to check
>>>>>>> was_recursively_verified()
>>>>>>> first. I valued clean code over potentially avoiding a function call
>>>>>>> to was_recursively_verified.
>>>>>>>
>>>>>>> What do you think?
>>>>>>>
>>>>>>> Tested with:
>>>>>>> jtreg hotspot tests
>>>>>>> new jtreg test for classinit tag
>>>>>>> performance testing with refworkload.
>>>>>>>
>>>>>>> Thanks, Max
>>>>>>
>>>>>
>>>
>