Missing class unload events over JDI with Java 17
S A
simeon.danailov.andreev at gmail.com
Thu Sep 2 13:21:47 UTC 2021
Hi David,
you are correct. This is why I added class loading and unloading logging
arguments, and see that the class unloading is done (I've listed this as
part of expected/actual output in my first e-mail). The classes *are* being
unloaded on time. Maybe that won't be the case in the future, but this is
not the topic here.
Anyway it seems the problem is already known:
https://bugs.openjdk.java.net/browse/JDK-8256811 (as recently commented on
the RHEL bugzilla ticket)
Adding a second GC trigger results in missing events being sent.
Best regards,
Simeon
On Thu, 2 Sept 2021 at 16:13, David Holmes <david.holmes at oracle.com> wrote:
> On 2/09/2021 10:05 pm, S A wrote:
> > Hi all,
> >
> > bisection lead to:
> >
> https://github.com/openjdk/jdk16/commit/ba721f5f2fbbf08e22a9993dce0087f46b1f5552
> > <
> https://github.com/openjdk/jdk16/commit/ba721f5f2fbbf08e22a9993dce0087f46b1f5552
> >
> >
> > I've opened: https://bugzilla.redhat.com/show_bug.cgi?id=2000557
> > <https://bugzilla.redhat.com/show_bug.cgi?id=2000557>
>
> private void unloadClasses() throws Exception {
> urlClassLoader.close();
> urlClassLoader = null;
> System.gc();
> System.runFinalization();
> }
>
> The above is not sufficient to guarantee class unloading has occurred.
> There are no specified ways to guarantee class unloading. It will depend
> on the GC in use as to what will be sufficient to trigger class unloading.
>
> Cheers,
> David
>
> > Best regards,
> > Simeon
> >
> > On Wed, 1 Sept 2021 at 16:12, S A <simeon.danailov.andreev at gmail.com
> > <mailto:simeon.danailov.andreev at gmail.com>> wrote:
> >
> > Hi all,
> >
> > my team is currently evaluating OpenJDK 17 (the latest early access
> > build) for a part of our application. I've been able to get all our
> > relevant tests to work, except for one that checks class unload
> > events sent over JDI.
> >
> > Originally we added the test due to:
> > https://bugs.openjdk.java.net/browse/JDK-8227269
> > <https://bugs.openjdk.java.net/browse/JDK-8227269> (we wanted to be
> > sure no class unload events are lost despite the fix)
> >
> > The test is Eclipse based (Eclipse has its own JDI implementation)
> > and expects to receive a certain set of class unload events under
> > controlled debugging conditions. The test has been running on
> > OpenJDK 8 and OpenJDK 11 for over an year now, without failures. On
> > OpenJDK 17 however, the test seems to fail nearly always (but not at
> > 100% rate).
> >
> > I've created a plain Java snippet and was able to reproduce the
> > problem with jdb, see instructions below.
> >
> > In essence, I see all class unloading is done (I'm checking with "
> > -Xlog:class+load,class+unload") at the expected time. No amount of
> > waiting in the test or in the snippet (e.g. a loop with 50 ms sleeps
> > for several seconds after class unloading is triggered) helps with
> > receiving all expected class unload JDI events though. Sometimes all
> > of them are sent, sometimes none are sent and sometimes only a
> > partial set of events is sent.
> >
> > Could someone knowledgeable take a look?
> >
> > I'll try to find the changes that cause the problem (so far I've not
> > checked whether earlier OpenJDK releases are affected). I'll also
> > open a RHEL support case for this, but those take a while to get in
> > contact with OpenJDK developers.
> >
> > Best regards and thanks,
> > Simeon
> >
> >
> > *Reproduction:*
> > *
> > *
> > First, I've made a change to OpenJDK code to check whether all class
> > unload events are being sent (in case the Eclipse JDI implementation
> > broke for some reason with OpenJDK 17). Its a printf in
> eventHandler.c :
> >
> > diff --git a/src/jdk.jdwp.agent/share/native/libjdwp/eventHandler.c
> > b/src/jdk.jdwp.agent/share/native/libjdwp/eventHandler.c
> > index 2a5912f0777..19a91126e18 100644
> > --- a/src/jdk.jdwp.agent/share/native/libjdwp/eventHandler.c
> > +++ b/src/jdk.jdwp.agent/share/native/libjdwp/eventHandler.c
> > @@ -500,6 +500,7 @@ synthesizeUnloadEvent(void *signatureVoid, void
> > *envVoid)
> > char *durableSignature =
> > jvmtiAllocate((int)strlen(signature)+1);
> > (void)strcpy(durableSignature, signature);
> >
> > + printf("Sending class unload event for: %s\n",
> > durableSignature);
> > eventHelper_recordClassUnload(node->handlerID,
> > durableSignature,
> > eventBag);
> >
> > The snippet I use to reproduce the problem loads a few classes, then
> > unloads them. It is:
> >
> > import java.io.File;
> > import java.net.URL;
> > import java.net.URLClassLoader;
> >
> > public class TestClassUnloadEvents {
> >
> > public static void main(String[] args) throws Exception {
> > new TestClassUnloadEvents().execute();
> > }
> >
> > private URLClassLoader urlClassLoader;
> >
> > public void execute() throws Exception {
> > beforeClassLoading();
> > loadClasses();
> > afterClassLoading();
> > unloadClasses();
> > afterClassUnloading();
> > }
> >
> > private void loadClasses() throws Exception {
> > int numberOfClassesToLoad = Integer.valueOf("10");
> > String libraryPath = "classes.jar";
> > URL[] urls = {
> > new File(libraryPath).toURI().toURL()
> > };
> > urlClassLoader = new URLClassLoader(urls, null);
> > for (int i = 0; i < numberOfClassesToLoad; ++i) {
> > String className = "sample.C" + i;
> > Class<?> loadClass = urlClassLoader.loadClass(className);
> > loadClass.newInstance();
> > }
> > }
> >
> > private void unloadClasses() throws Exception {
> > urlClassLoader.close();
> > urlClassLoader = null;
> > System.gc();
> > System.runFinalization();
> > }
> >
> > public static void beforeClassLoading() {
> > System.out.println("BEFORE CLASS LOADING");
> > }
> >
> > public static void afterClassLoading() {
> > System.out.println("AFTER CLASS LOADING");
> > }
> >
> > public static void afterClassUnloading() {
> > System.out.println("AFTER CLASS UNLOADING");
> > }
> > }
> >
> > Create a jar file from the attached "classes.zip" (I would attach a
> > .jar directly but gmail is blocking jar attachments, even archived
> > ones; sorry about this). Place the "classes.jar" jar file in the
> > same folder as the snippet and from that folder run the snippet.
> E.g.:
> >
> > /data/git/jdk17/build/linux-x86_64-server-release/jdk/bin/java
> > -Xlog:class+load,class+unload
> > -agentlib:jdwp=transport=dt_socket,server=y,suspend=y,address=8080
> > TestClassUnloadEvents.java
> >
> > Then attach jdb with:
> >
> > /data/git/jdk17/build/linux-x86_64-server-release/jdk/bin/jdb
> > -attach 8080
> >
> > Input "resume", to let the application finish.
> >
> > Expected output that I sometimes see (with Java 11 I always see all
> > expected prints from the change, where event order is not relevant):
> >
> > ...
> > AFTER CLASS LOADING
> > [6.312s][info][class,load] java.io.RandomAccessFile$1 source:
> >
> /data/git/jdk17/build/linux-x86_64-server-release/jdk/modules/java.base
> > [6.315s][info][class,unload] unloading class sample.C9
> > 0x00000008001c5c30
> > [6.315s][info][class,unload] unloading class sample.C8
> > 0x00000008001c5a28
> > [6.315s][info][class,unload] unloading class sample.C7
> > 0x00000008001c5820
> > [6.315s][info][class,unload] unloading class sample.C6
> > 0x00000008001c5618
> > [6.315s][info][class,unload] unloading class sample.C5
> > 0x00000008001c5410
> > [6.315s][info][class,unload] unloading class sample.C4
> > 0x00000008001c5208
> > [6.315s][info][class,unload] unloading class sample.C3
> > 0x00000008001c5000
> > [6.315s][info][class,unload] unloading class sample.C2
> > 0x00000008001c4c10
> > [6.315s][info][class,unload] unloading class sample.C1
> > 0x00000008001c4a08
> > [6.315s][info][class,unload] unloading class sample.C0
> > 0x00000008001c4800
> > [6.325s][info][class,load ] java.lang.ref.Finalizer$2 source:
> >
> /data/git/jdk17/build/linux-x86_64-server-release/jdk/modules/java.base
> > Sending class unload event for: Lsample/C9;
> > Sending class unload event for: Lsample/C7;
> > Sending class unload event for: Lsample/C5;
> > Sending class unload event for: Lsample/C3;
> > Sending class unload event for: Lsample/C1;
> > Sending class unload event for: Lsample/C0;
> > Sending class unload event for: Lsample/C8;
> > Sending class unload event for: Lsample/C6;
> > Sending class unload event for: Lsample/C4;
> > Sending class unload event for: Lsample/C2;
> > [6.325s][info][class,load ] java.lang.ref.Finalizer$1 source:
> >
> /data/git/jdk17/build/linux-x86_64-server-release/jdk/modules/java.base
> > AFTER CLASS UNLOADING
> > ...
> >
> > Example output that I (often) see, which is unexpected:
> >
> > ...
> > AFTER CLASS LOADING
> > [4.863s][info][class,load] java.io.RandomAccessFile$1 source:
> >
> /data/git/jdk17/build/linux-x86_64-server-release/jdk/modules/java.base
> > [4.867s][info][class,unload] unloading class sample.C9
> > 0x00000008001c5c30
> > [4.867s][info][class,unload] unloading class sample.C8
> > 0x00000008001c5a28
> > [4.867s][info][class,unload] unloading class sample.C7
> > 0x00000008001c5820
> > [4.867s][info][class,unload] unloading class sample.C6
> > 0x00000008001c5618
> > [4.867s][info][class,unload] unloading class sample.C5
> > 0x00000008001c5410
> > [4.867s][info][class,unload] unloading class sample.C4
> > 0x00000008001c5208
> > [4.867s][info][class,unload] unloading class sample.C3
> > 0x00000008001c5000
> > [4.867s][info][class,unload] unloading class sample.C2
> > 0x00000008001c4c10
> > [4.867s][info][class,unload] unloading class sample.C1
> > 0x00000008001c4a08
> > [4.867s][info][class,unload] unloading class sample.C0
> > 0x00000008001c4800
> > [4.876s][info][class,load ] java.lang.ref.Finalizer$2 source:
> >
> /data/git/jdk17/build/linux-x86_64-server-release/jdk/modules/java.base
> > Sending class unload event for: Lsample/C9;
> > Sending class unload event for: Lsample/C7;
> > Sending class unload event for: Lsample/C5;
> > Sending class unload event for: Lsample/C3;
> > [4.876s][info][class,load ] java.lang.ref.Finalizer$1 source:
> >
> /data/git/jdk17/build/linux-x86_64-server-release/jdk/modules/java.base
> > AFTER CLASS UNLOADING
> > ...
> >
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://mail.openjdk.java.net/pipermail/serviceability-dev/attachments/20210902/5035e8ad/attachment-0001.htm>
More information about the serviceability-dev
mailing list