RFR: JDK-8232773: ClassLoading Debug Output for Specific Classes
Ioi Lam
ioi.lam at oracle.com
Tue Oct 29 20:36:15 UTC 2019
For tracing classes that fail to load:
Currently, if a delegated class loader can't find a class, if will throw
ClassNotFoundException in its loadClass() method. So if we run with
-Xlog:exceptions, we may get lots of CNFEs for classes that are
eventually found. This doesn't happen with the JDK's built-in
boot/platform loaders anymore, as they use package information to avoid
unnecessary delegation. However, with JavaEE or OSGi type of apps, such
superfluous CNFE traces may make it difficult to analyze classes that
actually fail to load.
One thing the VM can help is to provide logging where a class has
definitely failed to load. This can be done by logging
in SystemDictionary::load_shared_class, when the upcall to
ClassLoader.loadClass() throws an exception.
====
$ hg diff
diff -r 94fe833a244b src/hotspot/share/classfile/systemDictionary.cpp
--- a/src/hotspot/share/classfile/systemDictionary.cpp Thu Oct 10
10:48:31 2019 -0700
+++ b/src/hotspot/share/classfile/systemDictionary.cpp Tue Oct 29
13:31:23 2019 -0700
@@ -52,6 +52,7 @@
#include "interpreter/interpreter.hpp"
#include "jfr/jfrEvents.hpp"
#include "logging/log.hpp"
+#include "logging/logMessage.hpp"
#include "logging/logStream.hpp"
#include "memory/filemap.hpp"
#include "memory/heapShared.hpp"
@@ -1506,7 +1507,20 @@
vmSymbols::loadClass_name(),
vmSymbols::string_class_signature(),
string,
- CHECK_NULL);
+ THREAD);
+ if (HAS_PENDING_EXCEPTION) {
+ if (log_is_enabled(Info, class, exceptions)) {
+ ResourceMark rm(THREAD);
+ LogMessage(class, exceptions) msg;
+ stringStream debug_stream;
+ ClassLoaderData *loader_data = class_loader_data(class_loader);
+ debug_stream.print("Failed to load class %s by [",
java_lang_String::as_quoted_ascii(string()));
+ loader_data->print_value_on(&debug_stream);
+ debug_stream.print("]");
+ msg.info("%s", debug_stream.as_string());
+ }
+ return NULL;
+ }
assert(result.get_type() == T_OBJECT, "just checking");
oop obj = (oop) result.get_jobject();
====
Here are some examples. Note that the second case will produce 5
separate CNFE logs for the java.lang.XXX class if -Xlog:exceptions is
used instead.
$ java -Xlog:class+exceptions -cp ~/tmp HelloX
[0.665s][info][class,exceptions] Failed to load class HelloX by [loader
data: 0x00007f3328511550
for instance a
'jdk/internal/loader/ClassLoaders$AppClassLoader'{0x000000045104f998}]
$ java d -Xlog:class+exceptions -cp ~/tmp java.lang.XXX
[0.655s][info][class,exceptions] Failed to load class java.lang.XXX by
[loader data: 0x00007f3fa0510ed0
for instance a
'jdk/internal/loader/ClassLoaders$AppClassLoader'{0x000000045104f9a0}]
We can probably print the full call stack as well, with the "trace"
logging level, if that's useful.
Thanks
- Ioi
On 10/29/19 12:30 PM, Mandy Chung wrote:
> Hi Adam,
>
> It'd be useful to provide a few typical scenarios that customers run
> into.
>
> That would give better understanding on the problem "hard to diagnose
> why a given class was not loaded" and help the consideration on
> alternatives. The debug output could produce lots of trace output
> but the output does not clearly indicate the initiating class is. I
> wonder if the problem you are looking at is related to JDK-6747450 [1]
> or really tracing the class loader delegation and search path. Or
> maybe Java Flight Recorder is a better candidate? Without knowing
> specific of the problems customers have, perhaps VM logging can be
> enhanced to trace the initiating class and class loader?
>
> Mandy
> [1] https://bugs.openjdk.java.net/browse/JDK-6747450
>
> On 10/29/19 5:08 AM, Adam Farley8 wrote:
>> Hey All,
>>
>> To restart (and re-centre) the chat on this:
>>
>> The issue I'm trying to solve is that it's hard to determine why a given
>> class was not loaded by OpenJDK.
>>
>> The solution I proposed was additional (optional) debug output from the
>> different classloaders.
>>
>> This way we can find out:
>>
>> - Whether any classloaders tried to load the class from your class'
>> location (by displaying all locations they try to load the class from).
>> - Which type of ClassLoaders tried to find your class.
>> - Which classpath each ClassLoader tried to use.
>> - Which modules were consulted.
>> etc etc.
>>
>> Currently, it seems the only debug information available in this regard
>> centres around:
>>
>> - Classes that were successfully loaded
>> and
>> - Exceptions when the class couldn't be loaded.
>>
>> So my questions are:
>>
>> 1) Am I trying to solve the right problem here?
>>
>> 2) Is there any support for this solution in principle, despite the fact
>> that the webrev in its current form is...unrefined?
>>
>> 3) Is there a better way to get this information, with or without a code
>> change?
>>
>> Advice or opinions are appreciated.
>>
>>
>> Bug:https://bugs.openjdk.java.net/browse/JDK-8232773
>>
>> Rough example webrev:http://cr.openjdk.java.net/~afarley/8232773/webrev/
>> Best Regards
>>
>> Adam Farley
>> IBM Runtimes
>>
>>
>>
>>
>> From: David Holmes<david.holmes at oracle.com>
>> To: Martin Buchholz<martinrb at google.com>
>> Cc: Ioi Lam<ioi.lam at oracle.com>, core-libs-dev
>> <core-libs-dev at openjdk.java.net>, Adam Farley8<adam.farley at uk.ibm.com>
>> Date: 24/10/2019 05:22
>> Subject: [EXTERNAL] Re: RFR: JDK-8232773: ClassLoading Debug
>> Output
>> for Specific Classes
>>
>>
>>
>> Hi Martin,
>>
>> This is going a bit OT I think ...
>>
>> On 24/10/2019 1:24 pm, Martin Buchholz wrote:
>>> On Tue, Oct 22, 2019 at 3:58 PM David Holmes
>>> <david.holmes at oracle.com <mailto:david.holmes at oracle.com>> wrote:
>>>
>>>
>>> Perhaps one aspect of the class loading/resolution/initialization
>>> process that can lead to confusion here is that if a class
>>> fails to
>>> execute its static initialization then it is marked as
>>> Erroneous and
>>> all
>>> subsequent attempts to use that class result in
>>> NoClassDefFoundError
>>> being thrown. If the original ExceptionInInitializerError got
>> swallowed
>>> somewhere then that can cause great confusion as to why the later
>> NCDFE
>>> occurs. The VM logging should help in that case - though I'd
>>> have to
>>> confirm that (if it doesn't that should be fixed).
>>>
>>>
>>> I had a need to debug an error in a <clinit> this week and was again
>>> frustrated by the difficulty.
>>> Classes falling into Erroneous state are rare so it seems reasonable to
>>> save the exception as a cause for the subsequent NCDFE (probably can't
>>> fix the misleading name of the exception)
>> So as you know such a request existed:
>>
>> https://urldefense.proofpoint.com/v2/url?u=https-3A__bugs.openjdk.java.net_browse_JDK-2D8048190&d=DwIDaQ&c=jf_iaSHvJObTbx-siA1ZOg&r=P5m8KWUXJf-CeVJc0hDGD9AQ2LkcXDC0PMV9ntVw5Ho&m=AfL8IyQ5gm4a9cA4orx0EnUwiGqvG6rei-DuA8gA0jQ&s=pzILDarpf9cN_MvQFqk1u3YZqFzSCRbBZVoRdFw4lS4&e=
>>
>>
>> and was closed as it was considered that TraceExceptions (now
>> -Xlog:exceptions) would provide the additional information. As noted in
>> that bug there are also semantic issues about recording the cause of an
>> exception in thread B, with an exception object that was thrown in
>> thread A. So unless someone comes up with a very convincing argument, or
>> else it prepared to do the work, I don't see that being re-opened.
>>
>>> I couldn't find a way to get hotspot to report the stack trace of all
>>> exceptions that are thrown; -Xlog:exceptions=trace does not .
>> -Xlog:exceptions shows where the exception is thrown and how it proceeds
>> up the stack. It doesn't print the full stacktrace. That seems like a
>> logging request for the Throwable constructor, or fillInStackTrace, to
>> me, rather than trying to have the VM do it. IIRC we store minimal VM
>> information in the backTrace which is expanded when needed into the full
>> StacktraceElements array.
>>> I was also frustrated that a StackOverflowError failed to report the
>>> name of the thread and the stack size that was exceeded. But
>>> -Xlog:threads*=trace helped there.
>> The issue there is that SOE instances are allocated natively without
>> executing any Java code (as we have run out of the Java stack) so we
>> can't (easily) create a String message for the exception. However
>> -Xlog:exceptions could be expanded to report that information at the
>> point we throw the SOE. I filed - JDK-8232923.
>>
>> Cheers,
>> David
>>
>>
>>
>>
>> Unless stated otherwise above:
>> IBM United Kingdom Limited - Registered in England and Wales with number
>> 741598.
>> Registered office: PO Box 41, North Harbour, Portsmouth, Hampshire
>> PO6 3AU
>>
>
More information about the core-libs-dev
mailing list