RFR: 8079408: Reimplement TraceClassLoading, TraceClassUnloading, and TraceClassLoaderData with Unified Logging.
Ioi Lam
ioi.lam at oracle.com
Mon Jan 25 03:49:00 UTC 2016
Hi Max:
Looks good overall. Just some minor nits in the code, and a suggestion
for the test.
classFileParser.cpp:
copyright date
classLoaderData.cpp:
wrong copyright date
This comment is superfluous and can be removed.
617 // It's OK to do safe points now (and we need to do that in JavaCalls::call_virtual)
systemDictionary.cpp:
copyright date
Remove the "else" here. These should be two independent "if" blocks
(see ClassLoadingService::notify_class_loaded).
1308 else if (log_is_enabled(Debug, classload)) {
nmethod.cpp:
Remove "]":
1317 " unloadable], Method*(" INTPTR_FORMAT
klass.cpp:
Remove [] and de-capitalize
407 log_trace(classunload)("[Unlinking class (sibling) %s]",
sibling->external_name());
globals.hpp:
copyright date
ClassLoadUnloadTest.java:
Testing for class unloading is tricky, so instead of rolling your
own code to force class unloading, it's better to use the
ClassUnloadCommon library.
You have
39 private static class ClassUnloadTestMain {
40
41 static String klass = "public class Empty {"
42 + " public void bigLoop(){}"
43 + " public String toString() { return
\"nothing\"; } }";
44
45 public static volatile WeakReference<ByteCodeLoader>
clweak;
46 public static byte[] garbage;
47
48 public static void main(String... args) throws Exception {
49 ByteCodeLoader cl = new ByteCodeLoader("Empty",
InMemoryJavaCompiler.compile("Empty", klass));
50 Class<?> c = cl.loadClass("Empty");
51 Object o = c.newInstance();
52 Method m = c.getMethod("bigLoop");
53
54 for ( int i=0; i<10001; i++){
55 m.invoke(o);
56 }
57
58 clweak = new WeakReference<>(cl);
59 cl = null; c = null; o = null; m = null;
60 while(clweak.get() != null) {
61 garbage = new byte[8192];
62 System.gc();
63 }
64 }
65 }
Example of using ClassUnloadCommon can be found in
hotspot/test/runtime/ClassUnload/UnloadTest.java
public class UnloadTest {
private static String className = "test.Empty";
public static void main(String... args) throws Exception {
run();
}
private static void run() throws Exception {
final WhiteBox wb = WhiteBox.getWhiteBox();
ClassUnloadCommon.failIf(wb.isClassAlive(className), "is not
expected to be alive yet");
ClassLoader cl = ClassUnloadCommon.newClassLoader();
Class<?> c = cl.loadClass(className);
Object o = c.newInstance();
ClassUnloadCommon.failIf(!wb.isClassAlive(className), "should be
live here");
cl = null; c = null; o = null;
ClassUnloadCommon.triggerUnloading();
ClassUnloadCommon.failIf(wb.isClassAlive(className), "should have
been unloaded");
}
}
In your case, you can even remove the whitebox calls, and just use:
private static void run() throws Exception {
ClassLoader cl = ClassUnloadCommon.newClassLoader();
Class<?> c = cl.loadClass(className);
cl = null; c = null;
ClassUnloadCommon.triggerUnloading();
}
Thanks
- Ioi
On 1/21/16 4:22 PM, Max Ockner wrote:
> Hello all,
> This fix is now working again with the new changes incorporated.
>
> New webrev: http://cr.openjdk.java.net/~mockner/classload.03/
>
> I responded to all comments from Ioi and Coleen.
> My answer to Ioi's first question is option #2.
>
> Max
>
> On 1/8/2016 8:57 PM, Ioi Lam wrote:
>>
>>
>> On 1/8/16 3:54 PM, Coleen Phillimore wrote:
>>>
>>> Hi, I have a bunch of comments that Ioi may have to help answer
>>> because I had some questions about how the logging output comes out.
>>>
>>> http://cr.openjdk.java.net/~mockner/classload.01/src/share/vm/classfile/classLoaderData.cpp.udiff.html
>>>
>>>
>>> I think these can be UL-ized with less lines. There's no need to
>>> check if log_is_enabled here.
>>>
>>> *!if (TraceClassLoaderData && Verbose&& class_loader() != NULL) {*
>>> *!tty->print_cr("is_anonymous: %s",
>>> class_loader()->klass()->internal_name());*
>>> *!if (_log_is_enabled(Trace, classloaderdata)_&& class_loader() !=
>>> NULL) {*
>>> *!_outputStream* log = LogHandle(classloaderdata)::trace_stream(_);*
>>> *+ log->print_cr("is_anonymous: %s",
>>> class_loader()->klass()->internal_name());*
>>> }
>>>
>>> *!if (class_loader() != NULL) {*
>>> *!tty->print_cr("is_anonymous: %s",
>>> class_loader()->klass()->internal_name());*
>>> *+ log_trace(classloaderdata)("is_anonymous: %s",
>>> class_loader()->klass()->internal_name());*
>>> }
>>>
>>> What does this come out looking like? It seems like it's going to
>>> have [classloaderdata] in front of every line printed. I think this
>>> wants to be all one log line.
>>>
>>> *+ outputStream* log = LogHandle(classloaderdata)::debug_stream();*
>>> *+ log->print("create class loader data " INTPTR_FORMAT, p2i(cld));*
>>> *+ log->print(" for instance " INTPTR_FORMAT " of %s", p2i((void
>>> *)cld->class_loader()),*
>>> *+ cld->loader_name());*
>>> *+ *
>>> *+ if (string.not_null()) {*
>>> *+ log->print(": ");*
>>> *+ java_lang_String::print(string(), log);*
>>> *+ } *
>>> [classloaderdata] create class loader data <address>
>>> [classloaderdata] for instance <addr> of some name
>>> [classloaderdata] :
>>> [classloaderdata] some string
>>>
>> The UL JEP says this in http://openjdk.java.net/jeps/158
>> "Goals ... Print line-at-a-time (no interleaving within same line)"
>>
>> log->print() is line-buffered. So all of these will be concatenated
>> into the same buffer until the final log->cr() or log->print_cr(), at
>> which point the whole line will be printed (with a single
>> [classloaderdata] prefix).
>>
>> Here's an example:
>>
>> $ java -Xlog:classloaderdata=debug -cp ~/tmp Foo
>> [0.780s][debug ][classloaderdata] create class loader data
>> 0x00007f71704d6940 for instance 0x000000041103dea0 of
>> sun/misc/Launcher$AppClassLoader:
>> "sun.misc.Launcher$AppClassLoader at 722c41f4"
>>
>>>
>>> http://cr.openjdk.java.net/~mockner/classload.01/src/share/vm/memory/filemap.cpp.udiff.html
>>>
>>>
>>> You don't need to check log_is_enabled. log_debug macro does that.
>>> 2 instances in this file.
>>>
>>> *+ if (log_is_enabled(Debug, classload)) {*
>>> *+ log_debug(classload)("[Add main shared path (%s) %s]",
>>> (cpe->is_jar_file() ? "jar" : "dir"), name);*
>>> *+ } *
>>>
>>>
>>> http://cr.openjdk.java.net/~mockner/classload.01/src/share/vm/oops/instanceKlass.cpp.udiff.html
>>>
>>>
>>> Do you want this to come out with fewer lines? Maybe the messages
>>> should be collected in a tempStream and printed out at the end? LIke
>>> in this file:
>>> http://cr.openjdk.java.net/~rprotacio/8144953/src/share/vm/c1/c1_Runtime1.cpp.udiff.html
>>>
>>>
>> There's no need to use the tempStream, since the UL log already
>> handles buffering.
>>
>> If my understanding of UL buffering is correct, I think the use of
>> tempStream should be removed as a clean up.
>>
>>> There's a bunch of tty->print's still in this function.
>>>
>>> *+ Handle class_loader(loader_data->class_loader());*
>>> *+ tty->print(" source: %s", class_loader->klass()->external_name()); *
>>>
>>> This could be simplified avoiding the Handle, which is not needed.
>>>
>>> *+ tty->print(" source: %s",
>>> loader_data->class_loader()->klass()->external_name());*
>>>
>>> Is the loader_data argument to print_loading_log simply the
>>> instanceKLass::_class_loader_data field? In which case you can
>>> remove the argument and have:
>>>
>>> *+ tty->print(" source: %s", class_loader()->klass()->external_name());
>>> *
>>>
>> The original code (from classFileParser.cpp) is this:
>>
>> tty->print("[Loaded %s from %s]\n", ik->external_name(),
>> _loader_data->class_loader()->klass()->external_name());
>>
>> I suppose _loader_data->class_loader() in that context should be
>> exactly the same as class_loader() inside the
>> InstanceKlass::print_loading_log function, so your suggestion should
>> work.
>>
>>> Obviously not to tty.
>>
>> You're right. The "tty->print" should be changed to log->print in
>> InstanceKlass::print_loading_log. What I don't understand is why the
>> output looks just fine.
>>
>> I never noticed these during my testing because the lines that use
>> tty->print are uncommon and did not show up. I'll try to come up with
>> a test case (I think it has something to do with reflection proxies
>> ...).
>>
>>
>> Thanks
>> - Ioi
>>>
>>> http://cr.openjdk.java.net/~mockner/classload.01/src/share/vm/prims/jvmtiEnv.cpp.udiff.html
>>>
>>>
>>> This one can be condensed also
>>>
>>> *!if (_log_is_enabled(Info, classload)_) {*
>>> *!_outputStream* log = LogHandle(classload)::info_stream(_);*
>>> *+ log->print_cr("[Opened %s]", zip_entry->name());*
>>> }
>>>
>>> to
>>>
>>> *+ log_info(classload)("[Opened %s]", zip_entry->name());
>>>
>>> *
>>> http://cr.openjdk.java.net/~mockner/classload.01/src/share/vm/runtime/arguments.cpp.udiff.html
>>>
>>> Yes, I think -verbose:class should be converted to UL. Ioi's #2 in
>>> his previous mail.
>>>
>>> http://cr.openjdk.java.net/~mockner/classload.01/src/share/vm/services/classLoadingService.cpp.udiff.html
>>>
>>>
>>> The return value 'ret' isn't used. Either return an error if it
>>> returns and error (what errors does it return?) or don't have 'ret'.
>>>
>>> http://cr.openjdk.java.net/~mockner/classload.01/test/runtime/logging/ClassLoadUnload.java.html
>>>
>>>
>>> Test looks great to me!
>>>
>>> 150 checkFor("[classload]", "java.lang.Object", "source:");
>>> 151 checkFor("[classunload]", "[Unloading class");
>>>
>>> Can this be:
>>>
>>> 150 checkFor("[classload]", "java.lang.Object", "source:",
>>> "[classunload]", "[Unloading class");
>>>
>>> To not start a new process?
>>>
>>> Thanks,
>>> Coleen
>>>
>>> On 1/8/16 2:10 AM, Max Ockner wrote:
>>>> Hello,
>>>> Please review this unified logging conversion for several related
>>>> flags in the class loading system.
>>>>
>>>> Bugs:
>>>> https://bugs.openjdk.java.net/browse/JDK-8079408 (classload,
>>>> classloaderdata)
>>>> https://bugs.openjdk.java.net/browse/JDK-8142506 (classunload)
>>>>
>>>> Webrev: http://cr.openjdk.java.net/~mockner/classload.01/
>>>>
>>>> Summary:
>>>>
>>>> There are two separate issues here. Originally Ioi and I began
>>>> working on these fixes in parallel, but eventually it became
>>>> obvious that the classload and classunload tags needed to be
>>>> implemented together. This change is a combination of Ioi's change
>>>> for 8079408 and my change for 8142506.
>>>>
>>>> (1) "-XX:+TraceClassLoading" ==> "-Xlog:classload=info"
>>>> This flag is added to the alias table. More verbose logging exists
>>>> at level debug (one level of verbosity up from info)
>>>>
>>>> (2) "-XX:+TraceClassUnLoading" ==> "-Xlog:classunload=info"
>>>> This flag is added to the alias table. More verbose logging exists
>>>> at level trace (converted from uses of WizardMode)
>>>>
>>>> (3) "-XX:+TraceClassLoaderData" ==> "-Xlog:classloaderdata=debug"
>>>>
>>>> The changes to TraceClassLoading and TraceClassUnloading also
>>>> effected the implementation of "-verbose:class"
>>>>
>>>> Tested with: jtreg runtime, runThese with "-Xlog:classload=trace
>>>> -Xlog:classunload=trace -Xlog:classloaderdata=trace".
>>>>
>>>> If you have questions about the updates to the classloading log,
>>>> Ioi can give a better answer than I can.
>>>>
>>>> Thanks,
>>>> Max
>>>>
>>>>
>>>>
>>>>
>>>
>>
>
More information about the hotspot-runtime-dev
mailing list