RFR: 8153535: Convert TraceRedefineClasses to Unified Logging

[David Holmes]

On 7/05/2016 2:28 AM, Robbin Ehn wrote:
> 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?)

I was just suggesting to look at how timers already interact with UL and 
whether that could work here. If simple enhancements to TraceTime were 
needed to achieve that, that is okay. If they turn out to be completely 
incompatible then so be it.

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

That isn't a justification. But if Coleen is okay with losing it so be it.

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

Yes - exactly. Not sure where we are getting crossed-lines here. There 
are a number of 'levels' for RC tracing defined as powers-of-2 that can 
be comined in a bit-mask. The range-trace macro allows you print out 
info if ANY of them are set. So previously we had a line that would be 
printed under numerous tracing conditions, and now it is only printed 
under a single UL condition.

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

I don't understand the motivation here. AFAIK noone ever said we must 
convert every single use of tty->print_cr into use of the UL framework 
instead. The RC_TRACE stuff does not seem like a good match for UL, so 
why not simply leave it as-is instead of putting in a subset of it that 
works with UL ?

Thanks,
David
-----

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