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
