RFR: 8153535: Convert TraceRedefineClasses to Unified Logging

[Robbin Ehn]

Hi David,

On 05/06/2016 03:58 PM, David Holmes wrote:
> 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. :)
>

UL TraceTimer log directly when it go out of scope, here we don't.
We summarize the 3 timers in 2 log lines.

So it's just matter of scoped, and as I said one scope is 220 lines, so 
I prefer the way it is, if you don't mind?

(or are you suggesting enhancements to TraceTime?)

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

This was just a random example.
If constantpool was on info I would of course not enable 
redefine+class*=info but instead use 
redefine+class+XXX,redefine+class+YYY,redefine+class+ZZZ, until happy!

0x00010000-0x00080000 looked to me it would make more sense to put them 
in same tag-set but with different level. But we can of course have them 
on same level but different tag.

>
> Many of our decisions seem to be driven by the perceived desire to use
> wildcards in a specific way. :(

No, just that certain logs have more in common than others, e.g. is 
about constantpool. And enabling all logs with that information seemed 
like a valid use-case.
(which happens to enable us to use wildcards for a few scenarios)

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

As I said, intentionally.

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

That might have been the original intention.
It evaluate to true as long as any bit between low and high are set.
E.g. in above 0x01001000 also is in range.


((bits & ((high << 1) - 1)) masks away high bits
and & ~(low - 1)) masks away low bits


This is also logical when reading the code, e.g. why should
"impl details: OopMapCache updates" stop
"detect calls to obsolete methods" ?

So RC_TRACE_TIME(somevalue, 0x00001000, 0x00001000) is the same as 
somevalue&0x00001000, correct?

But never the less, yes there are some drawbacks using UL.
My hope and intention was that we could live with it.

Thanks!

/Robbin

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