RFR: 8153535: Convert TraceRedefineClasses to Unified Logging
David Holmes
david.holmes at oracle.com
Fri May 6 13:58:01 UTC 2016
On 6/05/2016 5:12 PM, Robbin Ehn wrote:
> 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)
You'd need to look at the other UL connected timers. I can't recall them
off the top of my head. :)
>>
>>> 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
That seems somewhat of a self-justifying definition. Where did those
usecases come from? You seem to have decided that
redefine+class+constantpool is less important than other
redefine+class+XXX, and you've decided to use a wildcard which means you
need a way to disable redefine+class+constantpool and so you drop it to
debug instead of info.
Many of our decisions seem to be driven by the perceived desire to use
wildcards in a specific way. :(
>
>>
>>> 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.
Perhaps not but that functionality for debugging has still been lost.
> In the old code if either of those two bits were set it evaluated true.
> (regardless off other bits)
Not sure I follow that statement.
> Since I removed one bit, this is a boolean and was translated to:
> is "redefine, class, obsolete" enabled or not.
No it (the TRACE_RANGE) isn't a boolean it is 0x00001000 to 0x00001FFF.
The ranges provided a way of combining tracing levels in a simple way
that is very cumbersome with UL tagging. Essentially a TRACE_RANGE(from,
to, "xxx") would have to be written as:
if (log_is_enabled(A, info) ||
log_is_enabled(B, info) ||
... {
log("xxx");
}
for all A, B, C covered by the range.
Cheers,
David
> 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
>>>
More information about the hotspot-runtime-dev
mailing list