Why does some garbage not get collected when forcing a GC sweep in Kotlin JVM, depending on seemingly irrelevant factors?

Question

Context

I'm working on a Kotlin program which runs on the JVM and consumes large amounts of memory. While I do trust the garbage collector to (eventually) free memory used by objects which are no longer reachable, I don't trust future maintainers of the project (including my future self) – especially as the project progresses and becomes more evolved - to write the code in a way that makes sure that objects which are no longer needed are indeed unreachable.

So in order to reduce the risk, as part of my testing suite (which is already exhaustive with regards to the logic of the program's functionality) I'm also writing (or trying to write, with different degrees of success) various tests which aim to ensure that references aren't kept to objects which have run their course.

As this is quite difficult to do directly, the technique I'm using in the tests is to employ objects with finalizers, simulate the conditions when they're no longer needed, force garbage collection, and assert the finalizers have indeed run. (Note: my question is not about this technique per se, but if someone has comments or ideas for improvement or can propose alternatives – I'll be interested to hear!).

This generally works well, and can be shown to do the job, e.g. in TDD style: I write naive code which does the job as far as the business logic is concerned but doesn't take care of losing references to old objects, I write a test as described above, I make sure that the test fails, I add code to take care of memory (e.g., in simple cases, set references to null), and then see that the test passes.

My question

For some reason, my tests don't always work (clarification: I don't mean that they fail non-deterministically; I mean that some of the tests consistently work and some consistently fail). The real examples from the project contain lots of intricate, proprietary details, but I've managed to boil it down to the following minimal example:

import kotlin.test.*

class FinalizationNotifier(val notify: () -> Unit) { protected fun finalize() = notify() }

class GcTest {
    @Test fun `disposes of no-longer-used object`() {
        var numTimesHasBeenDisposed = 0
        // The following line allocates a (FinalizationNotifier) object, but keeps no reference to it
        f(FinalizationNotifier { numTimesHasBeenDisposed++ }) // Note call to f, which in turn calls println
        assertEquals(0, numTimesHasBeenDisposed) // Finalizer has not been run yet
        System.gc() // Force garbage collection
        Thread.sleep(1) // seems to be necessary to make sure finalizers have been run
        assertEquals(1, numTimesHasBeenDisposed) // Finalizer has indeed been run
    }
}

fun<T> f(value: T) { println(value) }

The test as written above passes, but if instead of calling f I call println directly – it fails (at the last assertion, i.e. the finalizer has not been run yet)! And my question is why that is, and/or what one should do in order to make sure (garbage gets collected and) finalizers are indeed run.

(Note: this is not about using println or calling my own functions; my real code is much more complex, and does call my own functions, and has nothing to do with printing. This is just a minimal example I've managed to come up with which shows the inconsistency.)

In case it matters, I'm using Kotlin 1.5.10 on Java 11.0.6 (on macOS).

Update:

I've written the two tests side-by-side (in file T.kt in package t); below please find the source code, as well as the disassembly (obtained using javap -c).

package t

import kotlin.test.*

class FinalizationNotifier(val notify: () -> Unit) { protected fun finalize() = notify() }

class GcTest {
    @Test fun `disposes of no-longer-used object when calling own function`() {
        var numTimesHasBeenDisposed = 0
        f(FinalizationNotifier { numTimesHasBeenDisposed++ }) // Note call to f, which in turn calls println
        assertEquals(0, numTimesHasBeenDisposed) // Finalizer has not been run yet
        System.gc() // Force garbage collection
        Thread.sleep(1) // seems to be necessary to make sure finalizers have been run
        assertEquals(1, numTimesHasBeenDisposed) // Finalizer has indeed been run
    }

    @Test fun `disposes of no-longer-used object when calling println directly`() {
        var numTimesHasBeenDisposed = 0
        println(FinalizationNotifier { numTimesHasBeenDisposed++ }) // Note direct call to println
        assertEquals(0, numTimesHasBeenDisposed) // Finalizer has not been run yet
        System.gc() // Force garbage collection
        Thread.sleep(1) // seems to be necessary to make sure finalizers have been run
        assertEquals(1, numTimesHasBeenDisposed) // This fails for some reason
    }
}

fun<T> f(value: T) { println(value) }

public final class t.FinalizationNotifier {
  public t.FinalizationNotifier(kotlin.jvm.functions.Function0<kotlin.Unit>);
    Code:
       0: aload_1
       1: ldc           #10                 // String notify
       3: invokestatic  #16                 // Method kotlin/jvm/internal/Intrinsics.checkNotNullParameter:(Ljava/lang/Object;Ljava/lang/String;)V
       6: aload_0
       7: invokespecial #19                 // Method java/lang/Object."<init>":()V
      10: aload_0
      11: aload_1
      12: putfield      #22                 // Field notify:Lkotlin/jvm/functions/Function0;
      15: return

  public final kotlin.jvm.functions.Function0<kotlin.Unit> getNotify();
    Code:
       0: aload_0
       1: getfield      #22                 // Field notify:Lkotlin/jvm/functions/Function0;
       4: areturn

  protected final void finalize();
    Code:
       0: aload_0
       1: getfield      #22                 // Field notify:Lkotlin/jvm/functions/Function0;
       4: invokeinterface #34,  1           // InterfaceMethod kotlin/jvm/functions/Function0.invoke:()Ljava/lang/Object;
       9: pop
      10: return
}
Compiled from "T.kt"
final class t.GcTest$disposes of no-longer-used object when calling own function$1 extends kotlin.jvm.internal.Lambda implements kotlin.jvm.functions.Function0<kotlin.Unit> {
  final kotlin.jvm.internal.Ref$IntRef $numTimesHasBeenDisposed;

  t.GcTest$disposes of no-longer-used object when calling own function$1(kotlin.jvm.internal.Ref$IntRef);
    Code:
       0: aload_0
       1: aload_1
       2: putfield      #13                 // Field $numTimesHasBeenDisposed:Lkotlin/jvm/internal/Ref$IntRef;
       5: aload_0
       6: iconst_0
       7: invokespecial #16                 // Method kotlin/jvm/internal/Lambda."<init>":(I)V
      10: return

  public final void invoke();
    Code:
       0: aload_0
       1: getfield      #13                 // Field $numTimesHasBeenDisposed:Lkotlin/jvm/internal/Ref$IntRef;
       4: getfield      #26                 // Field kotlin/jvm/internal/Ref$IntRef.element:I
       7: istore_1
       8: aload_0
       9: getfield      #13                 // Field $numTimesHasBeenDisposed:Lkotlin/jvm/internal/Ref$IntRef;
      12: iload_1
      13: iconst_1
      14: iadd
      15: putfield      #26                 // Field kotlin/jvm/internal/Ref$IntRef.element:I
      18: return

  public java.lang.Object invoke();
    Code:
       0: aload_0
       1: invokevirtual #29                 // Method invoke:()V
       4: getstatic     #35                 // Field kotlin/Unit.INSTANCE:Lkotlin/Unit;
       7: areturn
}
Compiled from "T.kt"
final class t.GcTest$disposes of no-longer-used object when calling println directly$1 extends kotlin.jvm.internal.Lambda implements kotlin.jvm.functions.Function0<kotlin.Unit> {
  final kotlin.jvm.internal.Ref$IntRef $numTimesHasBeenDisposed;

  t.GcTest$disposes of no-longer-used object when calling println directly$1(kotlin.jvm.internal.Ref$IntRef);
    Code:
       0: aload_0
       1: aload_1
       2: putfield      #13                 // Field $numTimesHasBeenDisposed:Lkotlin/jvm/internal/Ref$IntRef;
       5: aload_0
       6: iconst_0
       7: invokespecial #16                 // Method kotlin/jvm/internal/Lambda."<init>":(I)V
      10: return

  public final void invoke();
    Code:
       0: aload_0
       1: getfield      #13                 // Field $numTimesHasBeenDisposed:Lkotlin/jvm/internal/Ref$IntRef;
       4: getfield      #26                 // Field kotlin/jvm/internal/Ref$IntRef.element:I
       7: istore_1
       8: aload_0
       9: getfield      #13                 // Field $numTimesHasBeenDisposed:Lkotlin/jvm/internal/Ref$IntRef;
      12: iload_1
      13: iconst_1
      14: iadd
      15: putfield      #26                 // Field kotlin/jvm/internal/Ref$IntRef.element:I
      18: return

  public java.lang.Object invoke();
    Code:
       0: aload_0
       1: invokevirtual #29                 // Method invoke:()V
       4: getstatic     #35                 // Field kotlin/Unit.INSTANCE:Lkotlin/Unit;
       7: areturn
}
Compiled from "T.kt"
public final class t.GcTest {
  public t.GcTest();
    Code:
       0: aload_0
       1: invokespecial #8                  // Method java/lang/Object."<init>":()V
       4: return

  public final void disposes of no-longer-used object when calling own function();
    Code:
       0: new           #14                 // class kotlin/jvm/internal/Ref$IntRef
       3: dup
       4: invokespecial #15                 // Method kotlin/jvm/internal/Ref$IntRef."<init>":()V
       7: astore_1
       8: new           #17                 // class t/FinalizationNotifier
      11: dup
      12: new           #19                 // class "t/GcTest$disposes of no-longer-used object when calling own function$1"
      15: dup
      16: aload_1
      17: invokespecial #22                 // Method "t/GcTest$disposes of no-longer-used object when calling own function$1"."<init>":(Lkotlin/jvm/internal/Ref$IntRef;)V
      20: checkcast     #24                 // class kotlin/jvm/functions/Function0
      23: invokespecial #27                 // Method t/FinalizationNotifier."<init>":(Lkotlin/jvm/functions/Function0;)V
      26: invokestatic  #33                 // Method t/TKt.f:(Ljava/lang/Object;)V
      29: iconst_0
      30: invokestatic  #39                 // Method java/lang/Integer.valueOf:(I)Ljava/lang/Integer;
      33: aload_1
      34: getfield      #43                 // Field kotlin/jvm/internal/Ref$IntRef.element:I
      37: invokestatic  #39                 // Method java/lang/Integer.valueOf:(I)Ljava/lang/Integer;
      40: aconst_null
      41: iconst_4
      42: aconst_null
      43: invokestatic  #49                 // Method kotlin/test/AssertionsKt.assertEquals$default:(Ljava/lang/Object;Ljava/lang/Object;Ljava/lang/String;ILjava/lang/Object;)V
      46: invokestatic  #54                 // Method java/lang/System.gc:()V
      49: lconst_1
      50: invokestatic  #60                 // Method java/lang/Thread.sleep:(J)V
      53: iconst_1
      54: invokestatic  #39                 // Method java/lang/Integer.valueOf:(I)Ljava/lang/Integer;
      57: aload_1
      58: getfield      #43                 // Field kotlin/jvm/internal/Ref$IntRef.element:I
      61: invokestatic  #39                 // Method java/lang/Integer.valueOf:(I)Ljava/lang/Integer;
      64: aconst_null
      65: iconst_4
      66: aconst_null
      67: invokestatic  #49                 // Method kotlin/test/AssertionsKt.assertEquals$default:(Ljava/lang/Object;Ljava/lang/Object;Ljava/lang/String;ILjava/lang/Object;)V
      70: return

  public final void disposes of no-longer-used object when calling println directly();
    Code:
       0: new           #14                 // class kotlin/jvm/internal/Ref$IntRef
       3: dup
       4: invokespecial #15                 // Method kotlin/jvm/internal/Ref$IntRef."<init>":()V
       7: astore_1
       8: new           #17                 // class t/FinalizationNotifier
      11: dup
      12: new           #65                 // class "t/GcTest$disposes of no-longer-used object when calling println directly$1"
      15: dup
      16: aload_1
      17: invokespecial #66                 // Method "t/GcTest$disposes of no-longer-used object when calling println directly$1"."<init>":(Lkotlin/jvm/internal/Ref$IntRef;)V
      20: checkcast     #24                 // class kotlin/jvm/functions/Function0
      23: invokespecial #27                 // Method t/FinalizationNotifier."<init>":(Lkotlin/jvm/functions/Function0;)V
      26: astore_2
      27: iconst_0
      28: istore_3
      29: getstatic     #70                 // Field java/lang/System.out:Ljava/io/PrintStream;
      32: aload_2
      33: invokevirtual #75                 // Method java/io/PrintStream.println:(Ljava/lang/Object;)V
      36: iconst_0
      37: invokestatic  #39                 // Method java/lang/Integer.valueOf:(I)Ljava/lang/Integer;
      40: aload_1
      41: getfield      #43                 // Field kotlin/jvm/internal/Ref$IntRef.element:I
      44: invokestatic  #39                 // Method java/lang/Integer.valueOf:(I)Ljava/lang/Integer;
      47: aconst_null
      48: iconst_4
      49: aconst_null
      50: invokestatic  #49                 // Method kotlin/test/AssertionsKt.assertEquals$default:(Ljava/lang/Object;Ljava/lang/Object;Ljava/lang/String;ILjava/lang/Object;)V
      53: invokestatic  #54                 // Method java/lang/System.gc:()V
      56: lconst_1
      57: invokestatic  #60                 // Method java/lang/Thread.sleep:(J)V
      60: iconst_1
      61: invokestatic  #39                 // Method java/lang/Integer.valueOf:(I)Ljava/lang/Integer;
      64: aload_1
      65: getfield      #43                 // Field kotlin/jvm/internal/Ref$IntRef.element:I
      68: invokestatic  #39                 // Method java/lang/Integer.valueOf:(I)Ljava/lang/Integer;
      71: aconst_null
      72: iconst_4
      73: aconst_null
      74: invokestatic  #49                 // Method kotlin/test/AssertionsKt.assertEquals$default:(Ljava/lang/Object;Ljava/lang/Object;Ljava/lang/String;ILjava/lang/Object;)V
      77: return
}
Compiled from "T.kt"
public final class t.TKt {
  public static final <T> void f(T);
    Code:
       0: iconst_0
       1: istore_1
       2: getstatic     #13                 // Field java/lang/System.out:Ljava/io/PrintStream;
       5: aload_0
       6: invokevirtual #18                 // Method java/io/PrintStream.println:(Ljava/lang/Object;)V
       9: return
}

Answer 1

It seems, Kotlin’s println(…) function has a different behavior than Java’s System.out.println(…) statement, regarding the order of evaluation.

In Java when you write

System.out.println(new Object() { {
    System.setOut(new PrintStream(OutputStream.nullOutputStream()));
}});

The message will still be printed because the method receiver, System.out is evaluated, i.e. the field is read, first, before the argument expression is evaluated, i.e. the inner class object is created and its constructor executed. So the code will change System.out first, before printing using the value, System.out had before the change.

Therefore, the bytecode looks like

  0: getstatic     #35                 // Field java/lang/System.out:Ljava/io/PrintStream;
  3: new           #41                 // class my/test/EvaluationOrder$1
  6: dup
  7: invokespecial #43                 // Method my/test/EvaluationOrder$1."<init>":()V
 10: invokevirtual #44                 // Method java/io/PrintStream.println:(Ljava/lang/Object;)V

The first instruction pushes the value of System.out to the operand stack, then the more involved object instantiation sequence follows, new creates and pushes a new uninitialized object, dup duplicates the reference, the following invokespecial consumes one and executes the constructor.

After that the stack contains the old value of System.out, followed by the reference to the initialized object, suitable to invoke the println method.

The bytecode generated by Kotlin is different:

  8: new           #17                 // class t/FinalizationNotifier
 11: dup
 12: new           #65                 // class "t/GcTest$disposes of no-longer-used object when calling println directly$1"
 15: dup
 16: aload_1
 17: invokespecial #66                 // Method "t/GcTest$disposes of no-longer-used object when calling println directly$1"."<init>":(Lkotlin/jvm/internal/Ref$IntRef;)V
 20: checkcast     #24                 // class kotlin/jvm/functions/Function0
 23: invokespecial #27                 // Method t/FinalizationNotifier."<init>":(Lkotlin/jvm/functions/Function0;)V
 26: astore_2
 27: iconst_0
 28: istore_3
 29: getstatic     #70                 // Field java/lang/System.out:Ljava/io/PrintStream;
 32: aload_2
 33: invokevirtual #75                 // Method java/io/PrintStream.println:(Ljava/lang/Object;)V

Your use case is a bit more involved as the constructor invocation receives another freshly constructed object (instructions 12-20) but we can ignore this and focus on the other aspects.

The first cited instruction (number 8) is starting the creation of the object you’re going to print while the reading of System.out, as part of the print(…) function, is done afterwards, in instruction 29.

To bring these references in the order required for invokevirtual … println, i.e. [PrintStream, argument object], the generated code introduces a synthetic variable to hold the reference to the constructed object temporarily. Instruction 26, astore_2, stores the reference to the constructed object into variable #2. Then, as said, instruction 29 pushes the current value of System.out to the stack⁽¹⁾, and instruction 32, aload_2 loads the reference to the object from variable #2, which leads to the required stack contents to invoke println in instruction 33.

With one catch. Now, variable #2 contains a reference to the object and bytecode has no scopes nor variable deletion operations. The reference stays in the local variable until this variable is overwritten for a different purpose or the method returns. When we skim through the remaining code, we see that in this specific setup, variable #2 is not used again, therefore, when the code invokes System.gc(), the reference is still held in the synthetic variable and may prevent the garbage collection.

As explained in Can java finalize an object when it is still in scope? being referenced by a local variable is not preventing the garbage collection per se. Formally, the object is still eligible to garbage collection when it is not used beyond that point. But whether it gets garbage collected in practice, depends on the optimization state of the method. So it’s not surprising when this code reproducibly prevents garbage collection in your scenario.

If Kotlin supports using System.out.println(…) with the same behavior as Java instead of its built-in println(…) function, it should change the behavior.

⁽¹⁾ for whatever reason, instructions 27 and 28 store the constant zero in variable #3 which is never used. This doesn’t affect the behavior of the remaining code.

Answer 2

(Meta: answering my own question, not to diminish the accepted answer, but to add some information which might be useful to folks who happen to stumble upon similar issues and end up reading this.)

Cause

It seems the Kotlin compiler sometimes introduces local variables under the hood to store various values a function uses, for reasons which might not be apparent to the developer (in fact, I've got no idea why it does that; if somebody knows it will be cool if they add an answer or a comment). And once an object is referenced from a local variable, while in theory it can still be garbage-collected after the last use of that variable, it seems in practice it doesn't (at least in some set-ups, maybe not all – see this question for example).

Diagnosis

One way to diagnose such a situation is to look at the generated Java bytecode, e.g. by using javap -c, or one's IDE's show bytecode option if there is one (on Intellij IDEA it's under Tools -> Kotlin -> Show Kotlin Bytecode). Note: Make sure to view the actual bytecode or at least bytecode which is congruent with the project's settings. For example, by default Intellij currently displays Kotlin bytecode generated through the legacy Kotlin compiler rather than the newer compiler which uses Kotlin IR, and in some cases that's different to the actual code being run, which is compiled via Kotlin IR (see issue).

The bytecode will show store instructions for local variables, including such variables which are not explicitly defined in the code but rather added by the compiler.

For example, in the following excerpt from the bytecode posted in the question:

  public final void disposes of no-longer-used object when calling println directly();
    Code:
       0: new           #14                 // class kotlin/jvm/internal/Ref$IntRef
       3: dup
       4: invokespecial #15                 // Method kotlin/jvm/internal/Ref$IntRef."<init>":()V
       7: astore_1
       8: new           #17                 // class t/FinalizationNotifier
      11: dup
      12: new           #65                 // class "t/GcTest$disposes of no-longer-used object when calling println directly$1"
      15: dup
      16: aload_1
      17: invokespecial #66                 // Method "t/GcTest$disposes of no-longer-used object when calling println directly$1"."<init>":(Lkotlin/jvm/internal/Ref$IntRef;)V
      20: checkcast     #24                 // class kotlin/jvm/functions/Function0
      23: invokespecial #27                 // Method t/FinalizationNotifier."<init>":(Lkotlin/jvm/functions/Function0;)V
      26: astore_2

one can see the FinalizationNotifier instance being initialised starting at 8: and finishing just before 26:, and then 26: astore_2 keeps it in a local variable (no. 2; local variable no. 0 is the this instance, and no. 1 here is the var numTimesHasBeenDisposed = 0, initialised starting at 0: and stored in 7:).

When does it happen?

As said above, I don't really know why the Kotlin compiler does it. And I'm also far from knowing all the cases when it happens. But I did notice two distinct cases (the one from the minimal example in the question and the one from my actual use case):

When passing an expression to println: This is what happened in the example in the question. When invoking System.out.println directly, the generated bytecode first gets System.out to the stack, then computes the expression passed to it leaving it next on the stack, and then invokes the println method. But when calling Kotlin's println, it is the expression that is passed to it which gets computed first, and only afterwards – as if a part of the println call itself – the bytecode gets System.out. Without resorting to storing the value of the expression in a local variable, the two elements end up on the stack in the reversed order than the one needed for the actual invocation. One way for Kotlin to address this could have been to preserve the original order (this could theoretically have some implications on the semantics, though I can hardly see how this would make any difference in practice). Another would be to swap the values on the stack. But for some reason Kotlin uses a local variable.

When constructing an array: This is what happened in my actual use case. I was passing an ad-hoc built array to a function (through vararg, actually, but after trying out several cases it doesn't seem to make a difference). When compiling not through Kotlin IR the array was constructed on the stack, but when compiling the Kotlin IR the generated bytecode used a local variable to store the array.

If someone reading it has a similar problem in a similar case that might be the reason. And there may be other cases. Anyone aware of any is welcome to answer/comment/edit. Of course, you can diagnose the problem by looking at the bytecode as explained above, regardless of whether your case is listed here or not.

Remedy

I've managed to come up with three different approaches to tackle the situation:

• In the specific case of using println, one could simply call System.out.println directly.

• More generally, one can wrap the code which creates the additional variable(s) in another function (which can, but doesn't have to, be a nested function). This way the local variables created are no longer reachable when execution of the wrapping function ends, and they do get garbage-collected. (This is what the one test from the original question which does pass does.)

• Another option is to explicitly assign the value to a variable instead of letting Kotlin do that implicitly under the hood, and then assign something else to that variable (which must be a var, not a val) or mutate the value if it only serves as a container referencing the actual object we want garbage-collected (e.g. if it's an array one can clear it) later. (One can also make the variable nullable and assign null to it afterwards, but, depending on the specifics of the use case, that might sometimes require the use of some mechanism – e.g. the !! operator – to convert the value to the non-nullable type, which in turn is yet a new expression which might end up assigned to an implicit local variable, defeating the purpose of the whole transformation.)