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

[Ioi Lam]

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