8298783: java/lang/ref/FinalizerHistogramTest.java failed with "RuntimeException: MyObject is not found in test output" #24143

bchristi-git · 2025-03-20T22:35:23Z

I propose some cleanups to FinalizerHistogramTest.java to hopefully clear up the intermittent failures:

run with othervm: this test blocks the (global) finalizer thread, and also requires the (global) finalizer thread to enter the test's finalize() method
The test uses volatile ints, but sets them based on their current value, which is not reliable; convert to AtomicInteger
use PhantomReferences to ensure that at least two MyObjects have become unreachable. If one is stuck in finalize(), at least one is still waiting to be finalized and should show up in the histogram.

Progress

Change must be properly reviewed (1 review required, with at least 1 Reviewer)
Change must not contain extraneous whitespace
Commit message must refer to an issue

Issue

JDK-8298783: java/lang/ref/FinalizerHistogramTest.java failed with "RuntimeException: MyObject is not found in test output" (Bug - P4)

Reviewers

Jaikiran Pai (@jaikiran - Reviewer) Review applies to 3a7d12bf
Kim Barrett (@kimbarrett - Reviewer)

Reviewing

Using git

Checkout this PR locally:
$ git fetch https://git.openjdk.org/jdk.git pull/24143/head:pull/24143
$ git checkout pull/24143

Update a local copy of the PR:
$ git checkout pull/24143
$ git pull https://git.openjdk.org/jdk.git pull/24143/head

Using Skara CLI tools

Checkout this PR locally:
$ git pr checkout 24143

View PR using the GUI difftool:
$ git pr show -t 24143

Using diff file

Download this PR as a diff file:
https://git.openjdk.org/jdk/pull/24143.diff

Using Webrev

Link to Webrev Comment

bridgekeeper · 2025-03-20T22:36:17Z

👋 Welcome back bchristi! A progress list of the required criteria for merging this PR into master will be added to the body of your pull request. There are additional pull request commands available for use with this pull request.

openjdk · 2025-03-20T22:36:57Z

@bchristi-git This change now passes all automated pre-integration checks.

ℹ️ This project also has non-automated pre-integration requirements. Please see the file CONTRIBUTING.md for details.

After integration, the commit message for the final commit will be:

8298783: java/lang/ref/FinalizerHistogramTest.java failed with "RuntimeException: MyObject is not found in test output"

Reviewed-by: kbarrett, jpai

You can use pull request commands such as /summary, /contributor and /issue to adjust it as needed.

At the time when this comment was updated there had been 62 new commits pushed to the master branch:

03f0ec4: 8183348: Better cleanup for jdk/test/sun/security/pkcs12/P12SecretKey.java
4d2d129: 8355962: RISCV64 cross build fails after 8354996
56468c4: 8322810: Lambda expression types can't be classes
... and 59 more: https://git.openjdk.org/jdk/compare/8b16897b74cfdc3c2693e3ae7e05f3d8c6468ebe...master

As there are no conflicts, your changes will automatically be rebased on top of these commits when integrating. If you prefer to avoid this automatic rebasing, please check the documentation for the /integrate command for further details.

➡️ To integrate this PR with the above commit message to the master branch, type /integrate in a new comment.

openjdk · 2025-03-20T22:37:37Z

@bchristi-git The following label will be automatically applied to this pull request:

core-libs

When this pull request is ready to be reviewed, an "RFR" email will be sent to the corresponding mailing list. If you would like to change these labels, use the /label pull request command.

mlbridge · 2025-03-20T22:40:38Z

Webrevs

test/jdk/java/lang/ref/FinalizerHistogramTest.java

jaikiran · 2025-03-26T14:33:01Z

The FinalizerHistogramTest tests the java.lang.ref.FinalizerHistogram class. To do that it sets up a situation where it generates several MyObject instances and allows (hopes) that they are GCed. In the finalize() method of the MyObject class a forever blocking operation is intentionally done, so that the java.lang.ref.Finalizer class which is responsible for calling the finalize() method on this class becomes blocked when it calls MyObject.finalize() on one such MyObject instance. That way, the internal queue that the Finalizer class maintains accumulates additional objects whose finalize() needs to be called.

The test then prints out the contents of this internal queue and expects that there be at least one more MyObject instance in this queue awaiting their finalize() to be invoked. Most of the times this all works fine and the test sees the MyObject instance(s) in that queue and passes.

In the cases where this intermittently fails, what seems to be happening is that, out of the numerous MyObject instances that the test hopes will be GCed, just one of them gets GCed and the Finalizer calls that instance's finalize() method. The test notices that the finalize() has been invoked and immediately goes on to print out the contents of the internal queue of the Finalizer expecting to see more MyObject instances in it. It doesn't find any and ends up failing.

As noted, this is a test bug because in its current form, there's no guarantee that the internal queue would have (at that moment) any more instances queued up when the first GCed MyObject.finalize() method invoked.

The proposed change here updates the test in such a way that we wait for at least 2 instances of MyObject to be picked up for GC (and thus end up in that internal queue) and the MyObject.finalize() of the first instance blocks forever, thus providing a guarantee that when the test access that queue, it will find at least the second instance of MyObject in it.

I think the overall idea/change to this test looks good to me. I do have a comment about the implementation detail of this change which I've added inline.

test/jdk/java/lang/ref/FinalizerHistogramTest.java

jaikiran

Thank you Brent for the updates. Good catch on the PhantomReference usage in the test. The latest changes look good to me.

turbanoff · 2025-04-05T19:37:44Z

test/jdk/java/lang/ref/FinalizerHistogramTest.java

            lock.lock();
        }
    }

    public static void main(String[] argvs) {
        try {
            lock.lock();
-            for(int i = 0; i < objectsCount; ++i) {
+            refQForTwo = new RefQForTwo(new MyObject(), new MyObject());
+            for(int i = 2; i < OBJECTS_COUNT; ++i) {


Suggested change

for(int i = 2; i < OBJECTS_COUNT; ++i) {

for (int i = 2; i < OBJECTS_COUNT; ++i) {

jaikiran

Still looks good to me.

kimbarrett · 2025-04-27T10:10:58Z

test/jdk/java/lang/ref/FinalizerHistogramTest.java

+            }
+            System.out.println("ref1Cleared: " + refQForTwo.ref1Cleared);
+            System.out.println("ref2Cleared: " + refQForTwo.ref2Cleared);
+            System.out.println("trappedCount.intValue(): " + trappedCount.intValue());


This could be made completely reliable, and much simpler, by using WhiteBox.

Don't introduce RefQForTwo. (It doesn't provide reliable information.)

Use WhiteBox::fullGC() to trigger finalization, instead of ForceGC.

Use (new) WhiteBox::waitForReferenceProcessing() to wait until the
FinalReferences have been enqueued (and mostly trapped in the queue).

test/jdk/java/lang/ref/FinalizerHistogramTest.java

kimbarrett · 2025-05-03T00:35:44Z

test/jdk/java/lang/ref/FinalizerHistogramTest.java

+            do {
+                refProResult = wb.waitForReferenceProcessing();
+                System.out.println("waitForReferenceProcessing returned: " + refProResult);
+            } while (refProResult);


Why the spammy output? Why not just

while (wb.waitForReferenceProcessing()) {}

Right now, the test just it prints a single line:
waitForReferenceProcessing returned: false
and I expect this to continue to be true.

For intermittently failing tests, I'm inclined to add a little extra output as long as I'm fiddling with it anyway. That way, if the test ever starts failing again, we have some (hopefully useful) clues about what happened.

Right now, the test just it prints a single line: waitForReferenceProcessing returned: false and I expect this to continue to be true.

If reference processing is being slow because of load, that will be different.

For intermittently failing tests, I'm inclined to add a little extra output as long as I'm fiddling with it anyway. That way, if the test ever starts failing again, we have some (hopefully useful) clues about what happened.

OK.

bchristi-git · 2025-05-06T18:38:53Z

/integrate

openjdk · 2025-05-06T18:40:34Z

Going to push as commit fe29cad.
Since your change was applied there have been 107 commits pushed to the master branch:

0cb355e: 8356096: ISO 4217 Amendment 179 Update
5d17a28: 8353001: Remove leftover Security Manager parsing code in sun.security.util.Debug
08dd4a7: 8354273: Replace even more Unicode characters with ASCII
... and 104 more: https://git.openjdk.org/jdk/compare/8b16897b74cfdc3c2693e3ae7e05f3d8c6468ebe...master

Your commit was automatically rebased without conflicts.

openjdk · 2025-05-06T18:40:41Z

@bchristi-git Pushed as commit fe29cad.

💡 You may see a message that your pull request was closed with unmerged commits. This can be safely ignored.

test reliability improvements

64f88cd

openjdk bot added the rfr Pull request is ready for review label Mar 20, 2025

openjdk bot added the core-libs [email protected] label Mar 20, 2025

myankelev reviewed Mar 21, 2025

View reviewed changes

test/jdk/java/lang/ref/FinalizerHistogramTest.java Outdated Show resolved Hide resolved

test/jdk/java/lang/ref/FinalizerHistogramTest.java Outdated Show resolved Hide resolved

test/jdk/java/lang/ref/FinalizerHistogramTest.java Outdated Show resolved Hide resolved

bchristi-git added 2 commits March 21, 2025 11:36

rename counter variables to use 'Count'

efbe07b

'return' not needed in lambda

78f334a

jaikiran reviewed Mar 26, 2025

View reviewed changes

test/jdk/java/lang/ref/FinalizerHistogramTest.java Outdated Show resolved Hide resolved

convert to WeakRefs, use a RefQ, print ForceGC results

d104107

jaikiran reviewed Mar 28, 2025

View reviewed changes

test/jdk/java/lang/ref/FinalizerHistogramTest.java Outdated Show resolved Hide resolved

jaikiran approved these changes Mar 28, 2025

View reviewed changes

openjdk bot added the ready Pull request is ready to be integrated label Mar 28, 2025

turbanoff reviewed Apr 5, 2025

View reviewed changes

Merge branch 'master' into 8298783

cfbb423

jaikiran approved these changes Apr 27, 2025

View reviewed changes

kimbarrett suggested changes Apr 27, 2025

View reviewed changes

bchristi-git added 2 commits April 29, 2025 14:52

Merge branch 'master' into 8298783

3a7d12b

convert test to use WhiteBox

10c8a9e

openjdk bot removed the ready Pull request is ready to be integrated label Apr 29, 2025

kimbarrett suggested changes Apr 29, 2025

View reviewed changes

test/jdk/java/lang/ref/FinalizerHistogramTest.java Outdated Show resolved Hide resolved

test/jdk/java/lang/ref/FinalizerHistogramTest.java Outdated Show resolved Hide resolved

bchristi-git added 2 commits April 30, 2025 13:14

loop until ref proc returns false

0468fe7

remove unneeded 'trappedCount'

88b2687

kimbarrett reviewed May 3, 2025

View reviewed changes

kimbarrett approved these changes May 4, 2025

View reviewed changes

openjdk bot added the ready Pull request is ready to be integrated label May 4, 2025

openjdk bot added the integrated Pull request has been integrated label May 6, 2025

openjdk bot closed this May 6, 2025

openjdk bot removed ready Pull request is ready to be integrated rfr Pull request is ready for review labels May 6, 2025

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

8298783: java/lang/ref/FinalizerHistogramTest.java failed with "RuntimeException: MyObject is not found in test output" #24143

8298783: java/lang/ref/FinalizerHistogramTest.java failed with "RuntimeException: MyObject is not found in test output" #24143

bchristi-git commented Mar 20, 2025 •

edited by openjdk bot

Loading

bridgekeeper bot commented Mar 20, 2025

openjdk bot commented Mar 20, 2025 •

edited

Loading

openjdk bot commented Mar 20, 2025

mlbridge bot commented Mar 20, 2025 •

edited

Loading

jaikiran commented Mar 26, 2025

jaikiran left a comment

turbanoff Apr 5, 2025

jaikiran left a comment

kimbarrett Apr 27, 2025

kimbarrett May 3, 2025

bchristi-git May 4, 2025

kimbarrett May 4, 2025

bchristi-git commented May 6, 2025

openjdk bot commented May 6, 2025

openjdk bot commented May 6, 2025

	for(int i = 2; i < OBJECTS_COUNT; ++i) {
	for (int i = 2; i < OBJECTS_COUNT; ++i) {

8298783: java/lang/ref/FinalizerHistogramTest.java failed with "RuntimeException: MyObject is not found in test output" #24143

8298783: java/lang/ref/FinalizerHistogramTest.java failed with "RuntimeException: MyObject is not found in test output" #24143

Conversation

bchristi-git commented Mar 20, 2025 • edited by openjdk bot Loading

Progress

Issue

Reviewers

Reviewing

bridgekeeper bot commented Mar 20, 2025

openjdk bot commented Mar 20, 2025 • edited Loading

openjdk bot commented Mar 20, 2025

mlbridge bot commented Mar 20, 2025 • edited Loading

Webrevs

jaikiran commented Mar 26, 2025

jaikiran left a comment

Choose a reason for hiding this comment

turbanoff Apr 5, 2025

Choose a reason for hiding this comment

jaikiran left a comment

Choose a reason for hiding this comment

kimbarrett Apr 27, 2025

Choose a reason for hiding this comment

kimbarrett May 3, 2025

Choose a reason for hiding this comment

bchristi-git May 4, 2025

Choose a reason for hiding this comment

kimbarrett May 4, 2025

Choose a reason for hiding this comment

bchristi-git commented May 6, 2025

openjdk bot commented May 6, 2025

openjdk bot commented May 6, 2025

bchristi-git commented Mar 20, 2025 •

edited by openjdk bot

Loading

openjdk bot commented Mar 20, 2025 •

edited

Loading

mlbridge bot commented Mar 20, 2025 •

edited

Loading