Bug 2000557

Summary: Missing class unload events over JDI with Java 17
Product: Red Hat Enterprise Linux 8 Reporter: Simeon Andreev <simeon.andreev>
Component: java-17-openjdkAssignee: Andrew Dinn <adinn>
Status: CLOSED MIGRATED QA Contact: OpenJDK QA <java-qa>
Severity: unspecified Docs Contact:
Priority: unspecified    
Version: 8.6CC: ahughes, loskutov, mmillson, neugens, sgehwolf
Target Milestone: rcKeywords: MigratedToJIRA
Target Release: ---   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2023-09-12 21:52:16 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Attachments:
Description Flags
Jar with classes to load during reproduction. none

Description Simeon Andreev 2021-09-02 11:58:31 UTC 
Created attachment 1820023 [details]
Jar with classes to load during reproduction.

Description of problem:

We are evaluating OpenJDK 17 early access builds for a part of our product. We see missing class unload events received by Eclipse over JDI, when running a dedicated test to ensure class unload events are sent and received. Upon investigation, we can reproduce with a plain Java snippet and jdb. The problem is also seen with OpenJDK 16, but not with OpenJDK 15 (or, OpenJDK 11 and OpenJDK 8).

Version-Release number of selected component (if applicable):

OpenJDK 16
OpenJDK 17

Steps to Reproduce:

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 :

1. Apply the following patch on top of either OpenJDK 16 or OpenJDK 17 source code (e.g. from https://github.com/openjdk/jdk17.git) and compile the JDK (this allows seeing which class unload events will be sent over JDI):

	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);

2. Place the following Java snippet in some folder:

	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");
		}
	}

3. Place the attached "classes.jar" jar file in the same folder as the snippet.
4. 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
5. Attach jdb with:
    /data/git/jdk17/build/linux-x86_64-server-release/jdk/bin/jdb -attach 8080
6. Input "resume" for JDB, to let the application finish.
7. Repeat the previous steps, observe that some prints (if not all) for class unloads are often missing.

Actual results:

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
...

Expected results:


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
...


Additional info:

Using our test, I've bisected the bug to those 2 commits:

commit ba721f5f2fbbf08e22a9993dce0087f46b1f5552 (HEAD -> bad)
Author: Coleen Phillimore <coleenp>
Date:   Thu Nov 19 14:30:02 2020 +0000

    8212879: Make JVMTI TagMap table concurrent
    
    Co-authored-by: Kim Barrett <kbarrett>
    Co-authored-by: Coleen Phillimore <coleenp>
    Reviewed-by: stefank, ihse, zgu, eosterlund, sspitsyn, kbarrett

commit 3a4b90f0863571dd372af6afab71862f3946a78f (good)
Author: Sean Mullan <mullan>
Date:   Thu Nov 19 14:15:57 2020 +0000

    8202343: Disable TLS 1.0 and 1.1
    
    Reviewed-by: xuelei, dfuchs, coffeys

With HEAD at 3a4b90f0863571dd372af6afab71862f3946a78f, the problem is not seen. With HEAD at ba721f5f2fbbf08e22a9993dce0087f46b1f5552, the problem is seen. So I assume the cause is:

https://github.com/openjdk/jdk17/commit/ba721f5f2fbbf08e22a9993dce0087f46b1f5552
Comment 3 Andrey Loskutov 2021-09-02 12:37:35 UTC 
I believe this is same as https://bugs.openjdk.java.net/browse/JDK-8256811, which is linked to original optimization bug https://bugs.openjdk.java.net/browse/JDK-8212879
Comment 4 Simeon Andreev 2021-09-02 12:44:07 UTC 
(In reply to Andrey Loskutov from comment #3)
> I believe this is same as https://bugs.openjdk.java.net/browse/JDK-8256811,
> which is linked to original optimization bug
> https://bugs.openjdk.java.net/browse/JDK-8212879

I've tried adding more waiting in our test, as well as waiting in the snippet that is being debugged (to give the JVM a chance to send events). Neither helps. The jdb based example also finishes without the patched JDK code ever printing anything for some of the class unloads.

So if this is https://bugs.openjdk.java.net/browse/JDK-8256811, then the problem there is more than just delayed events; its lost events.
Comment 5 Simeon Andreev 2021-09-02 13:05:50 UTC 
I do see a 2nd GC trigger seems to get all events to be sent, at least with the snippet from the description (slightly adjusted) and jdb:

public void execute() throws Exception {
        beforeClassLoading();
        loadClasses();
        afterClassLoading();
        for (int i = 0; i < 5; ++i) {
        	unloadClasses();
        	afterClassUnloading();
        }
	}
	...
	private void unloadClasses() throws Exception {
	    if (urlClassLoader != null) {
			urlClassLoader.close();
		}
	    urlClassLoader = null;
	    System.gc();
	    System.runFinalization();
	}

...
AFTER CLASS LOADING
[4.287s][info][class,load] java.io.RandomAccessFile$1 source: /data/git/jdk17/build/linux-x86_64-server-release/jdk/modules/java.base
[4.290s][info][class,unload] unloading class sample.C9 0x00000008001c5c30
[4.290s][info][class,unload] unloading class sample.C8 0x00000008001c5a28
[4.290s][info][class,unload] unloading class sample.C7 0x00000008001c5820
[4.290s][info][class,unload] unloading class sample.C6 0x00000008001c5618
[4.290s][info][class,unload] unloading class sample.C5 0x00000008001c5410
[4.290s][info][class,unload] unloading class sample.C4 0x00000008001c5208
[4.290s][info][class,unload] unloading class sample.C3 0x00000008001c5000
[4.290s][info][class,unload] unloading class sample.C2 0x00000008001c4c10
[4.290s][info][class,unload] unloading class sample.C1 0x00000008001c4a08
[4.290s][info][class,unload] unloading class sample.C0 0x00000008001c4800
[4.299s][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;
[4.299s][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
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;
AFTER CLASS UNLOADING
AFTER CLASS UNLOADING
AFTER CLASS UNLOADING
AFTER CLASS UNLOADING
...

(from my 10-20 test runs, the 2nd GC would result in prints for any events that were missed in the first GC)

Same for our test, if I add a 2nd GC trigger JDI receives all class unload events as expected.

I'll have to check whether our application can have problems due to this. I remember Eclipse JDT using ClassUnloadEvent for something (HCR related maybe) but so far I'm not finding such code.
Comment 6 Simeon Andreev 2021-09-02 14:15:21 UTC 
Eclipse JDT has a cache, based on class loaded and unloaded events: org.eclipse.jdi.internal.VirtualMachineImpl.fCachedReftypes

I'm guessing we can construct a situation where a cache item is used after its respective class has been unloaded. I'm not sure what the implications are.


I think there also can be problems with "out of order" loads and unloads, see e.g.: https://bugs.eclipse.org/bugs/show_bug.cgi?id=449791

That is, when a class is loaded, and unloaded, then loaded and unloaded again. We could have load, load events arrive, and then unload unload events. So the 2nd load will replace the cache entry, and the first unload will remove that entry. I'll have to check whether such a sequence (load,load,unload,unload) can occur though. Likely the "delayed" unload will be sent before the 2nd load (though again, I'll have to double check).


The cache also is accessed by JDT HCR, see:

* org.eclipse.jdt.internal.debug.core.hcr.JavaHotCodeReplaceManager.redefineTypesJDK(JDIDebugTarget, List<IResource>, List<String>)
* org.eclipse.jdt.internal.debug.core.hcr.JavaHotCodeReplaceManager.doHotCodeReplace(List<JDIDebugTarget>, List<IResource>, List<String>)

Here though elements from the cache are being removed, and not iterated over. So I assume JDT HCR itself is "safe".


Possibly the impact for Eclipse is not that big, seeing that the missing unloads are sent on the next GC.
Comment 7 Simeon Andreev 2022-06-13 11:26:40 UTC 
The Eclipse-based test we have seems to still fail, from time to time. So apparently triggering GC twice is not sufficient to avoid the problem.

It might be that the 2nd GC trigger is ignored by the JVM - its hard to know. I do see JVM logging for the class unload events, as expected. But I have no way of knowing whether the 2nd GC resulted in any work being done, in particular detecting the class unloads and sending events for them (as implied by this comment: https://bugs.openjdk.org/browse/JDK-8256811?focusedCommentId=14397616&page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel#comment-14397616).

I think there was a deterministic way of triggering GC with Java 17, i.e. that the GC  triggers are always obeyed? Or that was depending on the GC strategy used?
Comment 8 Zhengyu 2022-06-13 17:48:14 UTC 
First of all, the bug is filed against java-11-openjdk, but seems should be jdk17.

The second, what exactly version of the "early release"? since I could not reproduce with current jdk17u head.
Comment 9 Zhengyu 2022-06-13 20:22:31 UTC 
Okay, I was able to reproduce with current jdk17u head once, so it is intermittent.
Comment 10 Simeon Andreev 2022-06-14 06:14:53 UTC 
There was no JDK 17 target when I created the bug (I'm not sure there is one now). And I was testing with early release at the time. Now I see it also with the official JDK 17 release.
Comment 11 Zhengyu 2022-06-14 14:21:00 UTC 
It is reproducible with jdk head, and yes, it is related to https://bugs.openjdk.java.net/browse/JDK-8256811 and Kim's suggestion seems to work. I will purpose the fix there.
Comment 12 Andrew John Hughes 2022-06-14 15:07:52 UTC 
(In reply to Simeon Andreev from comment #10)
> There was no JDK 17 target when I created the bug (I'm not sure there is one
> now). And I was testing with early release at the time. Now I see it also
> with the official JDK 17 release.

This is because it's filed against RHEL 7. Does it need to be? java-17-openjdk is available as an option for RHEL 8 & 9. We don't provide java-17-openjdk packages for RHEL 7.
Comment 13 Zhengyu 2022-06-14 15:11:53 UTC 
Based on comments, this is not a problem with java-11-openjdk, as JDK-8212879 is not in jdk11u.
Comment 14 Simeon Andreev 2022-06-15 05:48:04 UTC 
(In reply to Andrew John Hughes from comment #12)
> This is because it's filed against RHEL 7. Does it need to be?

We need a fix in OpenJDK 17, the RHEL version is irrelevant here. Please adjust it to RHEL 9 if this is needed.
Comment 16 Mike Millson 2022-06-15 14:49:13 UTC 
(In reply to Simeon Andreev from comment #14)
> (In reply to Andrew John Hughes from comment #12)
> > This is because it's filed against RHEL 7. Does it need to be?
> 
> We need a fix in OpenJDK 17, the RHEL version is irrelevant here. Please
> adjust it to RHEL 9 if this is needed.

I have moved it to RHEL8. Engineering can adjust as appropriate.
Comment 18 Zhengyu 2022-06-15 15:07:27 UTC 
PR for JDK20: https://github.com/openjdk/jdk/pull/9168

Will backport to 17u when ready.
Comment 27 Andrey Loskutov 2022-10-04 11:14:21 UTC 
(In reply to Zhengyu from comment #18)
> PR for JDK20: https://github.com/openjdk/jdk/pull/9168

Thank you!

> Will backport to 17u when ready.

Any estimation in which Java 17 build we can see the fix?
Comment 28 Andrew Dinn 2022-11-02 14:54:34 UTC 
The next release of jdk17u (January 2023) will include all the upstream fixes that address this problem.
Comment 29 Simeon Andreev 2022-11-02 15:02:08 UTC 
(In reply to Andrew Dinn from comment #28)
> The next release of jdk17u (January 2023) will include all the upstream
> fixes that address this problem.

Sounds great, thanks!
Comment 30 Simeon Andreev 2023-01-26 11:30:28 UTC 
OK, I validated with the RHEL 9 OpenJDK 17.0.6 packages. I also validated with the latest master from https://github.com/openjdk/jdk17u.git (top commit 2fe42855c48c49b515b97312ce64a5a8ef3af407 (HEAD -> master, tag: jdk-17.0.6-ga, tag: jdk-17.0.6+10, origin/master, origin/HEAD)). The bug is fixed.

Thank you very much!
Comment 31 RHEL Program Management 2023-09-12 21:50:57 UTC 
Issue migration from Bugzilla to Jira is in process at this time. This will be the last message in Jira copied from the Bugzilla bug.
Comment 32 RHEL Program Management 2023-09-12 21:52:16 UTC 
This BZ has been automatically migrated to the issues.redhat.com Red Hat Issue Tracker. All future work related to this report will be managed there.

Due to differences in account names between systems, some fields were not replicated.  Be sure to add yourself to Jira issue's "Watchers" field to continue receiving updates and add others to the "Need Info From" field to continue requesting information.

To find the migrated issue, look in the "Links" section for a direct link to the new issue location. The issue key will have an icon of 2 footprints next to it, and begin with "RHEL-" followed by an integer.  You can also find this issue by visiting https://issues.redhat.com/issues/?jql= and searching the "Bugzilla Bug" field for this BZ's number, e.g. a search like:

"Bugzilla Bug" = 1234567

In the event you have trouble locating or viewing this issue, you can file an issue by sending mail to rh-issues. You can also visit https://access.redhat.com/articles/7032570 for general account information.