Cleaner optimizaton #1536

pmconrad · 2023-08-03T09:09:23Z

Fixes #1535 (also fixes #1521 )

This PR fixes the cleaner overload issue by creating a Cleaner instance per thread so that each thread will clean up the objects it previously created.
An additional "Master Cleaner" cleans up after thread exits. The Master Cleaner terminates itself 1 minute after all registered objects have been cleaned up.

matthiasblaesing

Thank you, this indeed looks like a good improvement. Looking at the logic it seems to be an improvement and good stabilization.

This might need another look:

jna/src/com/sun/jna/internal/Cleaner.java

Lines 158 to 176 in 4a76b10

    
           while ((now = System.currentTimeMillis()) < lastNonEmpty + MAX_LINGER_MS || !deleteIfEmpty()) { 
        
               if (!cleanerImpls.isEmpty()) { lastNonEmpty = now; } 
        
               try { 
        
                   Reference<?> ref = impl.referenceQueue.remove(CLEANUP_INTERVAL_MS); 
        
                   if(ref instanceof CleanerRef) { 
        
                       ((CleanerRef) ref).clean(); 
        
                   } else { 
        
                       masterCleanup(); 
        
                   } 
        
               } catch (InterruptedException ex) { 
        
                   // Can be raised on shutdown. If anyone else messes with 
        
                   // our reference queue, well, there is no way to separate 
        
                   // the two cases. 
        
                   // https://groups.google.com/g/jna-users/c/j0fw96PlOpM/m/vbwNIb2pBQAJ 
        
                   break; 
        
               } catch (Exception ex) { 
        
                   Logger.getLogger(Cleaner.class.getName()).log(Level.SEVERE, null, ex); 
        
               } 
        
           }

Consider this situation:

If new threads allocating native memory are periodically created and end with an interval that is smaller than CLEANUP_INTERVAL_MS, every iteration of the while loop (158) will yield a CleanerRef in 161 and masterCleanup() will never be called. If now multiple threads are created (and are kept alive), that allocate native memory, the last allocation of these threads might not be collected, even if it should be gced, because for these cases cleanup is only done from cleanQueue, which is only called from masterCleanup then.

The Callback Cleanup Test failes on windows (also locally reproducible, I tested with JDK8 both 32bit and 64bit):

Appveyor (64bit):
https://ci.appveyor.com/project/matthiasblaesing/jna/build/job/2x995gulpks9il6y?fullLog=true#L2061
https://ci.appveyor.com/project/matthiasblaesing/jna/build/job/2x995gulpks9il6y?fullLog=true#L2092

Appveyor (32bit):
https://ci.appveyor.com/project/matthiasblaesing/jna/build/job/9423p77olylb56ua?fullLog=true#L2063
https://ci.appveyor.com/project/matthiasblaesing/jna/build/job/9423p77olylb56ua?fullLog=true#L2094

On windows 64bit I also got a test failure on a manual run:

test/com/sun/jna/different_package/CleanerTest.java

src/com/sun/jna/internal/Cleaner.java

pmconrad · 2023-08-15T08:59:42Z

If new threads allocating native memory are periodically created and end with an interval that is smaller than CLEANUP_INTERVAL_MS, every iteration of the while loop (158) will yield a CleanerRef in 161 and masterCleanup() will never be called. If now multiple threads are created (and are kept alive), that allocate native memory, the last allocation of these threads might not be collected, even if it should be gced, because for these cases cleanup is only done from cleanQueue, which is only called from masterCleanup then.

Good catch, thanks. Should be fixed now.

The Callback Cleanup Test failes on windows (also locally reproducible, I tested with JDK8 both 32bit and 64bit):
Appveyor (64bit): https://ci.appveyor.com/project/matthiasblaesing/jna/build/job/2x995gulpks9il6y?fullLog=true#L2061 https://ci.appveyor.com/project/matthiasblaesing/jna/build/job/2x995gulpks9il6y?fullLog=true#L2092
Appveyor (32bit): https://ci.appveyor.com/project/matthiasblaesing/jna/build/job/9423p77olylb56ua?fullLog=true#L2063 https://ci.appveyor.com/project/matthiasblaesing/jna/build/job/9423p77olylb56ua?fullLog=true#L2094

I've found and fixed a possible cause. Will see if it works.

On windows 64bit I also got a test failure on a manual run:

That's what I would expect if you ran the first commit only (test case to demonstrate #1535 ). Can you reproduce that with the latest commit?

matthiasblaesing · 2023-08-15T17:18:16Z

Windows is still a problem. The Linux side seems to cleanup nicely (github actions run clean).

These are only the amd64 ones:

On my virtual machine I get:

The first set of problems might be a to short test time, the latter a too small heap.

pmconrad · 2023-12-31T11:55:53Z

Sorry for the delay.
Rebased on latest master and refactored some tests to get rid of the windows-specific error. Works for me with 64bit Oracle JDK 1.8.0.

matthiasblaesing · 2024-01-11T18:47:29Z

The situation is much improved. What I'm seeing though is, that the cleaner thread does not shut down. From my POV it can't. The static com.sun.jna.internal.Cleaner.MY_INSTANCE holds a strong reference on a one cleaner per Thread (when at least one cleaner relevant action is executed in that thread). That strong reference in turn will prevent GC/shutdown of the Masterthread.

Could you please recheck this?

pmconrad · 2024-01-24T12:07:59Z

What I'm seeing though is, that the cleaner thread does not shut down. From my POV it can't. The static com.sun.jna.internal.Cleaner.MY_INSTANCE holds a strong reference on a one cleaner per Thread (when at least one cleaner relevant action is executed in that thread). That strong reference in turn will prevent GC/shutdown of the Masterthread.

Yes and no. The cleaner thread does not shut down as long as there are Cleaner instances alive. This is on purpose - the cleaner thread is required as long as the Cleaner instances could still be used for registering new cleanables.

The idea is that in the "interesting" cases, the Cleaner instances will eventually be GC'd because either

the threads holding Cleaner instances terminate, or
the Cleaner class is unloaded (which means the static ThreadLocal will eventually be GC'd).

If neither happens, the cleaner thread will (and needs to) stay alive.

I admit there is one edge case that is not covered by this, i.e. if an application uses JNA only during startup and then never again. In that case, the cleaner thread will stay alive and consume some (few) resources. If that is a problem, it can be circumvented by executing the initial JNA calls in a separate thread that shuts down after JNA is no longer needed.

Now that I've explained this, I'm not sure that the class unloading actually works. :-/ Will test.

matthiasblaesing · 2024-02-19T19:08:05Z

#1555 was created as reaction to #1521. It is not easy to get JNA unloaded. The pattern to use a static INSTANCE variable on the interface makes it hard to unload the library, but it is possible.

I disagree with the assessment that it is uncommon to call JNA methods from long running threads. For example can it be necessary to invoke functions from the EDT or using a thread pool. Firing up a separate thread to call into native is the opposite of a performance improvement and also might not be feasible at all.

pmconrad · 2024-06-19T17:16:34Z

I've simplified the Cleaner instance handling. It no longer relies on Thread instances being GC'd, which wasn't working as expected, nor on Java's ThreadLocal implementation, which wasn't either.
Instead I'm using a simple Map Thread->Cleaner, and let the MasterCleaner thread take over instances that are either no longer in active use, or that belong to dead threads. That should properly handle long-running threads. It should also allow class unloading once all to-be-cleaned-up references have been GC'd, but I'm unsure how to best test this.

matthiasblaesing

Thank you for the update! For a smoke test I use a setup based on this:

#1555 (comment)

Maven project: Test.zip

I used NetBeans for testing, opened the project and "Ran" the "Test" class with Debugging. I observed output and running threads. After the hostname is printed and the "JNA Cleaner" thread vanished, I put a breakpoint onto the first if(exit) { line (line 36). Using the debugger I set the variable exit to true. I allow the programm to continue and observe, that a new "JNA Cleaner" thread is spun up, when the second run method (40) is invoked. So shutting down and starting up again works.

Comments are left inline.

I ran ant checkstyle over this and checkstyle is not happy:

matthias@enterprise:~/src/jnalib$ ant checkstyle
Buildfile: /home/matthias/src/jnalib/build.xml

checkstyle:
[checkstyle] Running Checkstyle 8.17 on 579 files
[checkstyle] [ERROR] /home/matthias/src/jnalib/src/com/sun/jna/internal/Cleaner.java:138: Das Unterelement von 'block' hat eine unerwartete Einrückungstiefe von 20 (erwartet: 16). [Indentation]
[checkstyle] [ERROR] /home/matthias/src/jnalib/src/com/sun/jna/internal/Cleaner.java:139: Das Unterelement von 'block' hat eine unerwartete Einrückungstiefe von 20 (erwartet: 16). [Indentation]
[checkstyle] [ERROR] /home/matthias/src/jnalib/src/com/sun/jna/internal/Cleaner.java:140: Das Unterelement von 'block' hat eine unerwartete Einrückungstiefe von 20 (erwartet: 16). [Indentation]
[checkstyle] [ERROR] /home/matthias/src/jnalib/src/com/sun/jna/internal/Cleaner.java:141: 'while' hat eine unerwartete Einrückungstiefe von 20 (erwartet: 16). [Indentation]
[checkstyle] [ERROR] /home/matthias/src/jnalib/src/com/sun/jna/internal/Cleaner.java:142: 'if' hat eine unerwartete Einrückungstiefe von 24 (erwartet: 20). [Indentation]
[checkstyle] [ERROR] /home/matthias/src/jnalib/src/com/sun/jna/internal/Cleaner.java:143: 'try' hat eine unerwartete Einrückungstiefe von 24 (erwartet: 20). [Indentation]
[checkstyle] [ERROR] /home/matthias/src/jnalib/src/com/sun/jna/internal/Cleaner.java:144: Das Unterelement von 'try' hat eine unerwartete Einrückungstiefe von 28 (erwartet: 24). [Indentation]
[checkstyle] [ERROR] /home/matthias/src/jnalib/src/com/sun/jna/internal/Cleaner.java:145: 'if' hat eine unerwartete Einrückungstiefe von 28 (erwartet: 24). [Indentation]
[checkstyle] [ERROR] /home/matthias/src/jnalib/src/com/sun/jna/internal/Cleaner.java:146: Das Unterelement von 'if' hat eine unerwartete Einrückungstiefe von 32 (erwartet: 28). [Indentation]
[checkstyle] [ERROR] /home/matthias/src/jnalib/src/com/sun/jna/internal/Cleaner.java:147: 'if rcurly' hat eine unerwartete Einrückungstiefe von 28 (erwartet: 24). [Indentation]
[checkstyle] [ERROR] /home/matthias/src/jnalib/src/com/sun/jna/internal/Cleaner.java:149: 'if' hat eine unerwartete Einrückungstiefe von 28 (erwartet: 24). [Indentation]
[checkstyle] [ERROR] /home/matthias/src/jnalib/src/com/sun/jna/internal/Cleaner.java:150: Das Unterelement von 'if' hat eine unerwartete Einrückungstiefe von 32 (erwartet: 28). [Indentation]
[checkstyle] [ERROR] /home/matthias/src/jnalib/src/com/sun/jna/internal/Cleaner.java:151: Das Unterelement von 'if' hat eine unerwartete Einrückungstiefe von 32 (erwartet: 28). [Indentation]
[checkstyle] [ERROR] /home/matthias/src/jnalib/src/com/sun/jna/internal/Cleaner.java:152: 'if rcurly' hat eine unerwartete Einrückungstiefe von 28 (erwartet: 24). [Indentation]
[checkstyle] [ERROR] /home/matthias/src/jnalib/src/com/sun/jna/internal/Cleaner.java:153: 'try rcurly' hat eine unerwartete Einrückungstiefe von 24 (erwartet: 20). [Indentation]
[checkstyle] [ERROR] /home/matthias/src/jnalib/src/com/sun/jna/internal/Cleaner.java:158: Das Unterelement von 'catch' hat eine unerwartete Einrückungstiefe von 28 (erwartet: 24). [Indentation]
[checkstyle] [ERROR] /home/matthias/src/jnalib/src/com/sun/jna/internal/Cleaner.java:159: 'catch rcurly' hat eine unerwartete Einrückungstiefe von 24 (erwartet: 20). [Indentation]
[checkstyle] [ERROR] /home/matthias/src/jnalib/src/com/sun/jna/internal/Cleaner.java:160: Das Unterelement von 'catch' hat eine unerwartete Einrückungstiefe von 28 (erwartet: 24). [Indentation]
[checkstyle] [ERROR] /home/matthias/src/jnalib/src/com/sun/jna/internal/Cleaner.java:161: 'catch rcurly' hat eine unerwartete Einrückungstiefe von 24 (erwartet: 20). [Indentation]
[checkstyle] [ERROR] /home/matthias/src/jnalib/src/com/sun/jna/internal/Cleaner.java:162: 'while rcurly' hat eine unerwartete Einrückungstiefe von 20 (erwartet: 16). [Indentation]
[checkstyle] [ERROR] /home/matthias/src/jnalib/src/com/sun/jna/internal/Cleaner.java:163: Das Unterelement von 'block' hat eine unerwartete Einrückungstiefe von 20 (erwartet: 16). [Indentation]
[checkstyle] [ERROR] /home/matthias/src/jnalib/src/com/sun/jna/internal/Cleaner.java:164: 'block rcurly' hat eine unerwartete Einrückungstiefe von 16 (erwartet: 12). [Indentation]
[checkstyle] [ERROR] /home/matthias/src/jnalib/test/com/sun/jna/MasterCleanerTest.java:1: Zeile entspricht nicht der erwarteten Kopfzeile '^/\*( Copyright.*$|$)'. [header-check]
[checkstyle] [ERROR] /home/matthias/src/jnalib/test/com/sun/jna/internal/MasterAccessor.java:1: Die erforderliche Kopfzeile fehlt - Datei hat nicht genug Zeilen. [header-check]

BUILD FAILED
/home/matthias/src/jnalib/build.xml:1581: Got 24 errors and 0 warnings.

Total time: 4 seconds
matthias@enterprise:~/src/jnalib$

matthiasblaesing · 2024-06-30T18:52:04Z

src/com/sun/jna/internal/Cleaner.java

+        private void cleanQueue() {
+            if (lock.compareAndSet(false, true)) {
+                try {
+                    Reference<?> ref;
+                    while ((ref = referenceQueue.poll()) != null) {
+                        try {
+                            if (ref instanceof Cleanable) {
+                                ((Cleanable) ref).clean();
+                            }
+                        } catch (RuntimeException ex) {
+                            Logger.getLogger(Cleaner.class.getName()).log(Level.SEVERE, null, ex);
+                        }
+                    }
+                } finally {
+                    lock.set(false);
+                }


Why is this locking necessary? I would expect the referenceQueue#poll to ensure a reference is only delivered to one poller.

The API docs of ReferenceQueue do not mention that poll() is thread-safe, so I assume it isn't.

matthiasblaesing · 2024-06-30T19:55:08Z

src/com/sun/jna/internal/Cleaner.java

+                Cleaner cleaner = entry.getValue();
+                long currentCount = cleaner.counter.get();
+                if (currentCount == cleaner.lastCount // no new cleanables registered since last master cleanup interval -> assume it is no longer in use
+                        || !entry.getKey().isAlive()) { // owning thread died -> assume it is no longer in use
+                    it.remove();
+                    CleanerImpl impl = cleaner.impl;
+                    LOG.log(Level.FINE, () -> "MasterCleaner stealing cleaner " + impl + " from thread " + entry.getKey());
+                    referencedCleaners.add(impl);
+                    watchedCleaners.add(impl);
+                    register(cleaner, () -> {
+                        referencedCleaners.remove(impl);
+                        LOG.log(Level.FINE, "Cleaner {0} no longer referenced", impl);
+                    });
+                    cleaners.remove(cleaner);
+                } else {
+                    cleaner.lastCount = currentCount;
+                }


This looks strange and I think I see a problem. Consider a thread that does native work, then sleeps for a time longer time than MASTER_CLEANUP_INTERVAL_MS, and does this in a loop. While doing this a native reference is kept in the Thread. Then in each interation a new CleanerImpl will be constructed.

In any case I find it hard to see the relationship between cleaners, referencedCleaners and watchedCleaners, a short description might help here.

This might be simplified:

I would start with the currentCount == cleaner.lastCount case. Use this as an indicator, that the master thread should poll the reference queue, i.e. run Cleaner#cleanQueue().

Then I would adopt all cleaners, that have no cleanables registered anymore or associated to dead threads. The former one needs adoption to handle the possible race where the check for "no cleanables" happens and disassociation from the thread happens. The latter needs to latter to not keep dead threads around because of this.

Consider a thread that does native work, then sleeps for a time longer time than MASTER_CLEANUP_INTERVAL_MS, and does this in a loop. While doing this a native reference is kept in the Thread. Then in each interation a new CleanerImpl will be constructed.
...
The former one needs adoption to handle the possible race where the check for "no cleanables" happens

Yes.

I did consider what you suggest, and decided against it because I couldn't see a way to avoid the race without introducing some kind of synchronization in the Cleaner.. The original Cleaner implementation seemed to deliberately avoid synchronization, so I wanted to avoid it too. The price to be paid for this is the possibility of having more Cleaner instances than strictly required, but I think the overhead is small except in rather degenerate cases.

matthiasblaesing · 2024-06-30T20:03:10Z

test/com/sun/jna/MasterCleanerTest.java

@@ -0,0 +1,92 @@
+package com.sun.jna;


Missing license header.

matthiasblaesing · 2024-07-06T18:58:49Z

I just had another look at this and I think I see another problem related to the adopted cleaners. If I'm not mistaken, the situation could happen: the last active cleaner is determined to be stale and moved to watched/referenced cleaners. In the next cycle the MasterCleaner can shut down because MasterCleaner#cleaners is now empty. But the watched/referenced cleaners still hold the instances and these are not processes anymore.

matthiasblaesing reviewed Aug 5, 2023

View reviewed changes

test/com/sun/jna/different_package/CleanerTest.java Show resolved Hide resolved

src/com/sun/jna/internal/Cleaner.java Outdated Show resolved Hide resolved

pmconrad force-pushed the cleaner-opt branch from 6080be7 to 8512a00 Compare December 27, 2023 15:55

pmconrad and others added 11 commits June 19, 2024 18:55

Added test case for cleaner thread overload

4456513

Re-implemented Cleaner

cebfafa

Added missing license header

b04b83c

Make MasterCleaner private

8549647

Attempt to fix windows test failures

1464d73

Ensure that masterCleanup runs at least every 2*MASTER_CLEANUP_INTERVAL

5f43c72

Refactored GC wait loops

b2e1037

Added test for per-thread cleaner cleanup (failing)

16975a3

Simplification

1d086fe

Replaced ThreadLocal-based "stealing" with our own mechanism

432739c

Added logging

f03fed9

pmconrad force-pushed the cleaner-opt branch from c525bcd to f03fed9 Compare June 19, 2024 17:00

matthiasblaesing reviewed Jun 30, 2024

View reviewed changes

pmconrad added 3 commits July 3, 2024 11:25

Added missing license header

3ee2725

Make checkstyle happy

094aea6

Added explanation of Cleaner lifecycle

21d46ab

pmconrad force-pushed the cleaner-opt branch from d2ffb16 to 21d46ab Compare July 3, 2024 10:01

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Cleaner optimizaton #1536

Cleaner optimizaton #1536

pmconrad commented Aug 3, 2023

matthiasblaesing left a comment

pmconrad commented Aug 15, 2023

matthiasblaesing commented Aug 15, 2023

pmconrad commented Dec 31, 2023

matthiasblaesing commented Jan 11, 2024

pmconrad commented Jan 24, 2024

matthiasblaesing commented Feb 19, 2024

pmconrad commented Jun 19, 2024

matthiasblaesing left a comment

matthiasblaesing Jun 30, 2024

pmconrad Jul 3, 2024

matthiasblaesing Jun 30, 2024

pmconrad Jul 3, 2024

matthiasblaesing Jun 30, 2024

matthiasblaesing commented Jul 6, 2024

	while ((now = System.currentTimeMillis()) < lastNonEmpty + MAX_LINGER_MS \|\| !deleteIfEmpty()) {
	if (!cleanerImpls.isEmpty()) { lastNonEmpty = now; }
	try {
	Reference<?> ref = impl.referenceQueue.remove(CLEANUP_INTERVAL_MS);
	if(ref instanceof CleanerRef) {
	((CleanerRef) ref).clean();
	} else {
	masterCleanup();
	}
	} catch (InterruptedException ex) {
	// Can be raised on shutdown. If anyone else messes with
	// our reference queue, well, there is no way to separate
	// the two cases.
	// https://groups.google.com/g/jna-users/c/j0fw96PlOpM/m/vbwNIb2pBQAJ
	break;
	} catch (Exception ex) {
	Logger.getLogger(Cleaner.class.getName()).log(Level.SEVERE, null, ex);
	}
	}

Cleaner optimizaton #1536

Are you sure you want to change the base?

Cleaner optimizaton #1536

Conversation

pmconrad commented Aug 3, 2023

matthiasblaesing left a comment

Choose a reason for hiding this comment

pmconrad commented Aug 15, 2023

matthiasblaesing commented Aug 15, 2023

pmconrad commented Dec 31, 2023

matthiasblaesing commented Jan 11, 2024

pmconrad commented Jan 24, 2024

matthiasblaesing commented Feb 19, 2024

pmconrad commented Jun 19, 2024

matthiasblaesing left a comment

Choose a reason for hiding this comment

matthiasblaesing Jun 30, 2024

Choose a reason for hiding this comment

pmconrad Jul 3, 2024

Choose a reason for hiding this comment

matthiasblaesing Jun 30, 2024

Choose a reason for hiding this comment

pmconrad Jul 3, 2024

Choose a reason for hiding this comment

matthiasblaesing Jun 30, 2024

Choose a reason for hiding this comment

matthiasblaesing commented Jul 6, 2024