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.hol...@oracle.com>
To: Martin Buchholz<marti...@google.com>
Cc: Ioi Lam<ioi....@oracle.com>, core-libs-dev
<core-libs-dev@openjdk.java.net>, Adam Farley8<adam.far...@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.hol...@oracle.com <mailto:david.hol...@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
