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

Max Ockner max.ockner at oracle.com
Thu Dec 3 17:18:36 UTC 2015 

David,

This is a good suggestion. For this change I was just following the 
existing convention, but I will switch conventions for the next change.

Thanks,
Max

On 12/3/2015 1:36 AM, David Holmes wrote:
> 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
>>>>>>>
>>>>>>
>>>>
>>

More information about the hotspot-runtime-dev mailing list