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

[David Holmes]

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());

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());

---

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?

---

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.


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