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

[Max Ockner]

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