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

[Daniel D. Daugherty]

On 1/21/16 5: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,

A search of existing tests for use of TraceClassLoading revealed
some hits in both the jdk/test and hotspot/test dirs:

$ rgrep TraceClassLoading jdk/test hotspot/test
jdk/test/java/lang/ClassLoader/deadlock/TestCrossDelegate.sh: 
-verbose:class -XX:+TraceClassLoading -cp . \
jdk/test/java/lang/ClassLoader/deadlock/TestOneWayDelegate.sh: 
-verbose:class -XX:+TraceClassLoading -cp . \
hotspot/test/closed/runtime/AppCDS/JvmtiAddPath.java: 
run(check_appcds_enabled, appJar, "-XX:+TraceClassLoading", "JvmtiApp", 
"noadd"); // appcds should be enabled
hotspot/test/closed/runtime/AppCDS/JvmtiAddPath.java: 
run(check_appcds_disabled, appJar, "-XX:+TraceClassLoading", "JvmtiApp", 
"bootonly", addbootJar); // appcds should be disabled


A search of existing tests for use of TraceClassUnloading revealed
some hits in both the jdk/test and hotspot/test dirs:

$ rgrep TraceClassUnloading jdk/test hotspot/test
jdk/test/java/lang/instrument/appendToClassLoaderSearch/ClassUnloadTest.sh: 
$JAVA ${TESTVMOPTS} -Xverify:none -XX:+TraceClassUnloading \
jdk/test/closed/com/oracle/jfr/runtime/TestClassUnloadEvent.java: * @run 
main/othervm -XX:+UnlockCommercialFeatures -XX:+FlightRecorder 
-XX:+TraceClassUnloading -Xlog:gc -Xmx16m TestClassUnloadEvent
hotspot/test/compiler/jsr292/CallSiteDepContextTest.java: * @run 
main/bootclasspath -Xbatch -XX:+IgnoreUnrecognizedVMOptions 
-XX:+TraceClassUnloading


A search of existing tests for use of TraceClassLoaderData
revealed no hits in either the jdk/test or hotspot/test dirs.


For the tests that use either TraceClassLoading or TraceClassUnloading,
you'll want to update the tests to use your new style options and, more
importantly, you'll need to check the tests to see if they depend on
any of the output formats that may have changed.

Dan


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