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. GivenI 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*=traceThat 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 = REMOVEDI'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! /RobbinCheers, DavidThanks! /RobbinThanks, David0x00004000 = "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
