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

[Coleen Phillimore]

Hi Max,

This looks pretty good.  It's a large change!  A couple of comments:

http://cr.openjdk.java.net/~mockner/classload.03/src/share/vm/classfile/classFileParser.cpp.udiff.html

As Harold pointed out earlier this change should check for 'else'.

*!if (_log_is_enabled(Info, classload)_) {*
*!_ik->print_loading_log(LogLevel::Info, _loader_data, _stream)_;*
}  else
*+ if (log_is_enabled(Debug, classload)) {*
*+ ik->print_loading_log(LogLevel::Debug, _loader_data, _stream);*
}

http://cr.openjdk.java.net/~mockner/classload.03/src/share/vm/memory/filemap.cpp.udiff.html

Doesn't this need to have a log_trace(classload)("...") in the three 
places you removed the conditional TraceClassLoading && Verbose?

Or did you and Ioi decide to not output anything for -Xlog:classload ?

http://cr.openjdk.java.net/~mockner/classload.03/src/share/vm/runtime/arguments.cpp.udiff.html

Doesn't the copyright go the wrong way?  Looks like it's updated to 2015 
from 2016?

It would be nice if the alias table lines up wrt to the semicolons.

http://cr.openjdk.java.net/~mockner/classload.03/src/share/vm/services/classLoadingService.cpp.udiff.html

This is inconsistent.  I think in 
ClassLoadingService::reset_trace_class_unloading, don't have the return 
code 'ret' that you don't use for anything.

That's all,  These are pretty minor but I think I'd like to see the 
final change.

Thanks!
Coleen

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