RFR: 8079408: Reimplement TraceClassLoading, TraceClassUnloading, and TraceClassLoaderData with Unified Logging.

Rachel Protacio rachel.protacio at oracle.com
Mon Jan 25 22:04:39 UTC 2016


Looks good (excepting the changed mentioned by Ioi/Coleen)! The jtreg 
test needs to be normalized a bit, though. Namely, you can look at the 
header for ClassResolutionTest.java:

    /*
      * @test ClassResolutionTest
      * @bug 8144874
      * @library /testlibrary
      * @build jdk.test.lib.OutputAnalyzer jdk.test.lib.ProcessTools
      * @run driver ClassResolutionTest
      */

    import jdk.test.lib.OutputAnalyzer;
    import jdk.test.lib.ProcessTools;
    import java.lang.ref.WeakReference;
    import java.lang.reflect.Method;

Where you should import the specific OutputAnalyzer and ProcessTools and 
@build them.

Also I think the ProcessBuilder function calls in your code were based 
on my incorrect tests before, so they should be formatted with one 
argument per line.

Thanks!
Rachel

On 1/21/2016 7: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