RFR: 8079408: Reimplement TraceClassLoading, TraceClassUnloading, and TraceClassLoaderData with Unified Logging.
Rachel Protacio
rachel.protacio at oracle.com
Mon Jan 25 22:04:39 UTC 2016
Looks good (excepting the changed mentioned by Ioi/Coleen)! The jtreg
test needs to be normalized a bit, though. Namely, you can look at the
header for ClassResolutionTest.java:
/*
* @test ClassResolutionTest
* @bug 8144874
* @library /testlibrary
* @build jdk.test.lib.OutputAnalyzer jdk.test.lib.ProcessTools
* @run driver ClassResolutionTest
*/
import jdk.test.lib.OutputAnalyzer;
import jdk.test.lib.ProcessTools;
import java.lang.ref.WeakReference;
import java.lang.reflect.Method;
Where you should import the specific OutputAnalyzer and ProcessTools and
@build them.
Also I think the ProcessBuilder function calls in your code were based
on my incorrect tests before, so they should be formatted with one
argument per line.
Thanks!
Rachel
On 1/21/2016 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
>>>>
>>>>
>>>>
>>>>
>>>
>>
>
More information about the hotspot-runtime-dev
mailing list