RFR: 8153535: Convert TraceRedefineClasses to Unified Logging

[David Holmes]

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.

> 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 
they use different tag sets they could really all be "info" for their set.

> 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.");
-    }


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
>