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

Tue Jan 26 17:14:05 UTC 2016

On 1/26/16 7:45 AM, Daniel D. Daugherty wrote:
> 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.
Note that TraceClassLoading is implicitly enabled when -verbose or 
-verbose:class are specified in the command line (see arguments.cpp), so 
there could be other tests that depend on the output of TraceClassLoading

I think for tests that use only -verbose/verbose:class, but do not 
explicitly specify TraceClassLoading, we can leave their command-lines 
alone, but need to fix the test bodies if they depend on the specific 
output format.

To run all the hotspot tests on the supported platforms, the easiest is 
to use RBT with

     --test hotspot/test/:hotspot_all

Thanks
- Ioi

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