RFR: 8153535: Convert TraceRedefineClasses to Unified Logging

Fri May 6 07:12:44 UTC 2016

Hi David, thanks for taking the time looking at this!

On 05/06/2016 07:20 AM, David Holmes wrote:
> Hi Robbin,
>
> Please see comments far below regarding mapping ...
>
> On 4/05/2016 5:25 AM, Robbin Ehn wrote:
>> Hi all,
>>
>> Please review this.
>>
>> This changeset moves redefine classes tracing to UL.
>>
>> Bug: https://bugs.openjdk.java.net/browse/JDK-8153535
>> Webrev: http://cr.openjdk.java.net/~rehn/8153535/rev_01/webrev/
>
> src/share/vm/prims/jvmtiRedefineClasses.cpp
>
> I wonder whether the RC timers can be better integrated as was done with
> other use of timers with logging? A scope-based Timer class would fix
> the problem of conditionally starting timers, but unconditionally
> stopping them.

Since I saw no harm in calling elapsedTimer.stop() so I did it this way.

Let me know you you want me to do scoped instead. (one of the scopes are 
really bid)

>
>> Passes testsuits
>> jdk/test/:jdk_jdi,hotspot/test/:hotspot_all,nsk.jvmti.testlist,nsk.jdi.testlist
>>
>> with:
>> -Xlog:redefine+class*=trace
>> (a few test won't run with extra options)
>>
>> -XX:TraceRedefineClasses=xyz turns on (aliased with)
>> "-Xlog:redefine+class*=info" and emits a warning.
>> (xyz is ignored)
>>
>> Thanks!
>>
>> /Robbin
>>
>> Example of useage:
>> -Xlog:redefine+class+constantpool*=debug
>> -Xlog:redefine+class+load=info
>> -Xlog:redefine+class*=debug,redefine+class+iklass*=trace
>>
>> Here is an example from a test:
>>
>> [20.279s][debug][redefine,class,update,vtables     ] vtable method
>> update: getOptions(()Ljava/util/Properties;), updated default = false
>> [20.279s][debug][redefine,class,subclass           ] updated count in
>> subclass=nsk.share.jvmti.ArgumentHandler to 197
>> [20.279s][info ][redefine,class,load               ] redefined
>> name=nsk.share.ArgumentParser, count=99 (avail_mem=6311580K)
>> [20.285s][trace][redefine,class,obsolete,mark      ] EMCP_cnt=8,
>> obsolete_cnt=0
>> [20.285s][trace][redefine,class,iklass,add         ] adding previous
>> version ref for nsk.share.jvmti.ArgumentHandler, EMCP_cnt=8
>> [20.285s][trace][redefine,class,iklass,add         ] scratch class not
>> added; no methods are running
>> [20.285s][info ][redefine,class,update             ] adjust:
>> name=nsk.share.jvmti.ArgumentHandler
>> [20.285s][debug][redefine,class,update,constantpool] cpc entry update:
>> getAgentOptionsString(()Ljava/lang/String;)
>> [20.285s][info ][redefine,class,update             ] adjust:
>> name=nsk.share.jvmti.ArgumentHandler
>> [20.285s][debug][redefine,class,update,constantpool] cpc entry update:
>> <init>(([Ljava/lang/String;)V)
>> [20.285s][info ][redefine,class,load               ] redefined
>> name=nsk.share.jvmti.ArgumentHandler, count=198 (avail_mem=6311580K)
>> [20.291s][trace][redefine,class,obsolete,mark      ] EMCP_cnt=3,
>> obsolete_cnt=0
>> [20.291s][trace][redefine,class,iklass,add         ] adding previous
>> version ref for nsk.share.jvmti.JVMTITest, EMCP_cnt=3
>> [20.291s][trace][redefine,class,iklass,add         ] scratch class not
>> added; no methods are running
>> [20.291s][info ][redefine,class,update             ] adjust:
>> name=nsk.share.jvmti.JVMTITest
>> [20.291s][debug][redefine,class,update,constantpool] cpc entry update:
>> commonInit(([Ljava/lang/String;)[Ljava/lang/String;)
>> [20.291s][info ][redefine,class,load               ] redefined
>> name=nsk.share.jvmti.JVMTITest, count=99 (avail_mem=6311580K)
>> [20.297s][trace][redefine,class,obsolete,mark      ] EMCP_cnt=3,
>> obsolete_cnt=0
>> [20.297s][trace][redefine,class,iklass,add         ] adding previous
>> version ref for nsk.share.TestBug, EMCP_cnt=3
>>
>> Mapping:
>
> Very unclear how you selected info/debug/trace for each of these. Given

I have select them after verbosity (looking at distribution after tests 
runs) and granularity. But sure it is a bit arbitrary.

> they use different tag sets they could really all be "info" for their set.

They use different level due for the use-case:

Enable info for all tagset containing the two tags redefine+class
-Xlog:redefine+class*=info

Also enable debug for constantpool
-Xlog:redefine+class*=info,redefine+class+constantpool=debug

Also enable trace for all updates
-Xlog:redefine+class*=info,redefine+class+constantpool=debug,redefine+class+update*=trace

>
>> RC_TRACE_MESG = "redefine, class, update" - info
>>
>> 0x00000001 = "redefine, class, load" - info
>> 0x00000001 = "redefine, class, load" - debug
>>
>> 0x00000002 = "redefine, class, load, exceptions" - info
>> 0x00000004 = "redefine, class, timer" - info
>> 0x00000008 = "redefine, class, subclass" - debug
>>
>> 0x00000100 = "redefine, class, obsolete, mark" - trace
>> 0x00000200 = "redefine, class, iklass, purge" - trace
>> 0x00000400 = "redefine, class, iklass, add" - trace
>> 0x00000800 = "redefine, class, breakpoint" - debug
>>
>> 0x00001000->0x00002000 = "redefine, class, obsolete" - trace
>> 0x00001000 = "redefine, class, obsolete" - trace
>> 0x00002000 = REMOVED
>
> I'm a little unclear about how the old ranges were supposed to work, but
> you have effectively removed them as far as I can see. A range of
> 1000->2000 would print out when "redefine, class, obsolete" was
> specified in conjunction with any, or all, or the preceding conditions -
> but now it will print only on that one condition.
>
> You also removed the debugging hooks related to this ie in
> sharedRuntime.cpp:
>
> -    if (RC_TRACE_ENABLED(0x00002000)) {
> -      // this option is provided to debug calls to obsolete methods
> -      guarantee(false, "faulting at call to an obsolete method.");
> -    }
>

Yes 0x00002000 was removed, because we can't have "class*=trace" 
enabling a guarantee.

In the old code if either of those two bits were set it evaluated true.
(regardless off other bits)

Since I removed one bit, this is a boolean and was translated to:
is "redefine, class, obsolete" enabled or not.

Thanks!

/Robbin

>
> Thanks,
> David
>
>> 0x00004000 = "redefine, class, obsolete, metadata" - trace
>> 0x00004000 = "redefine, class, dump" - trace
>>
>> 0x00008000 = "redefine, class, normalize" - trace
>>
>> 0x00010000 = "redefine, class, constantpool" - info
>> 0x00020000 = "redefine, class, constantpool" - debug
>> 0x00040000 = "redefine, class, constantpool" - trace
>> 0x00080000 = "redefine, class, constantpool" - trace
>>
>> 0x00100000-0x00400000 = "redefine, class, update" - info
>> 0x00100000 = "redefine, class, update, vtables" - debug
>> 0x00200000 = "redefine, class, update, itables" - debug
>> 0x00400000 = "redefine, class, update, constantpool" - debug
>>
>> 0x00800000 = "redefine, class, methodcomparator" - debug
>>
>> 0x01000000 = "redefine, class, nmethod" - debug
>> 0x02000000 = "redefine, class, annotation" - debug
>> 0x04000000 = "redefine, class, stackmap" - debug
>> 0x08000000 = "redefine, class, oopmap" - debug
>>