OutOfMemoryException despite using WeakHashMap

Question

If do not call System.gc(), the system will throw an OutOfMemoryException. I do not know why I need to call System.gc() explicitly; the JVM should call gc() itself, right? Please advise.

The following is my test code:

public static void main(String[] args) throws InterruptedException {
    WeakHashMap<String, int[]> hm = new WeakHashMap<>();
    int i  = 0;
    while(true) {
        Thread.sleep(1000);
        i++;
        String key = new String(new Integer(i).toString());
        System.out.println(String.format("add new element %d", i));
        hm.put(key, new int[1024 * 10000]);
        key = null;
        //System.gc();
    }
}

As following, add -XX:+PrintGCDetails to print out the GC info; as you see, actually, the JVM tries to do a full GC run, but fails; I still do not know the reason. It is very strange that if I uncomment the System.gc(); line, the result is positive:

add new element 1
add new element 2
add new element 3
add new element 4
add new element 5
[GC (Allocation Failure) --[PSYoungGen: 48344K->48344K(59904K)] 168344K->168352K(196608K), 0.0090913 secs] [Times: user=0.02 sys=0.00, real=0.01 secs] 
[Full GC (Ergonomics) [PSYoungGen: 48344K->41377K(59904K)] [ParOldGen: 120008K->120002K(136704K)] 168352K->161380K(196608K), [Metaspace: 5382K->5382K(1056768K)], 0.0380767 secs] [Times: user=0.09 sys=0.03, real=0.04 secs] 
[GC (Allocation Failure) --[PSYoungGen: 41377K->41377K(59904K)] 161380K->161380K(196608K), 0.0040596 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
[Full GC (Allocation Failure) [PSYoungGen: 41377K->41314K(59904K)] [ParOldGen: 120002K->120002K(136704K)] 161380K->161317K(196608K), [Metaspace: 5382K->5378K(1056768K)], 0.0118884 secs] [Times: user=0.02 sys=0.00, real=0.01 secs] 
Exception in thread "main" java.lang.OutOfMemoryError: Java heap space
    at test.DeadLock.main(DeadLock.java:23)
Heap
 PSYoungGen      total 59904K, used 42866K [0x00000000fbd80000, 0x0000000100000000, 0x0000000100000000)
  eden space 51712K, 82% used [0x00000000fbd80000,0x00000000fe75c870,0x00000000ff000000)
  from space 8192K, 0% used [0x00000000ff800000,0x00000000ff800000,0x0000000100000000)
  to   space 8192K, 0% used [0x00000000ff000000,0x00000000ff000000,0x00000000ff800000)
 ParOldGen       total 136704K, used 120002K [0x00000000f3800000, 0x00000000fbd80000, 0x00000000fbd80000)
  object space 136704K, 87% used [0x00000000f3800000,0x00000000fad30b90,0x00000000fbd80000)
 Metaspace       used 5409K, capacity 5590K, committed 5760K, reserved 1056768K
  class space    used 576K, capacity 626K, committed 640K, reserved 1048576K

Answer 1

JVM will call GC on it's own, but in this case it will be too little too late. It's not only GC who is responsible in clearing memory in this case. Map values are strongly reachable and are cleared by map itself when certain operations are invoked on it.

Here's the output if you turn on GC events (XX:+PrintGC):

add new element 1
add new element 2
add new element 3
add new element 4
add new element 5
add new element 6
add new element 7
[GC (Allocation Failure)  2407753K->2400920K(2801664K), 0.0123285 secs]
[GC (Allocation Failure)  2400920K->2400856K(2801664K), 0.0090720 secs]
[Full GC (Allocation Failure)  2400856K->2400805K(2590720K), 0.0302800 secs]
[GC (Allocation Failure)  2400805K->2400805K(2801664K), 0.0069942 secs]
[Full GC (Allocation Failure)  2400805K->2400753K(2620928K), 0.0146932 secs]
Exception in thread "main" java.lang.OutOfMemoryError: Java heap space

GC is not triggered up until the last attempt to put value into the map.

WeakHashMap can't clear stale entries until map keys occur on a reference queue. And the map keys do not occur on a reference queue until they are garbage collected. Memory allocation for new map value is triggered before map has any chance to clear itself. When memory allocation fails and triggers GC, map keys do get collected. But it's too little too late - not enough memory has been freed to allocate new map value. If you reduce the payload, you probably end up with enough memory to allocate new map value and stale entries will get removed.

Another solution could be wrapping values themselves into WeakReference. This will allow GC clear resources without waiting for map to do it on it's own. Here's the output:

add new element 1
add new element 2
add new element 3
add new element 4
add new element 5
add new element 6
add new element 7
[GC (Allocation Failure)  2407753K->2400920K(2801664K), 0.0133492 secs]
[GC (Allocation Failure)  2400920K->2400888K(2801664K), 0.0090964 secs]
[Full GC (Allocation Failure)  2400888K->806K(190976K), 0.1053405 secs]
add new element 8
add new element 9
add new element 10
add new element 11
add new element 12
add new element 13
[GC (Allocation Failure)  2402096K->2400902K(2801664K), 0.0108237 secs]
[GC (Allocation Failure)  2400902K->2400838K(2865664K), 0.0058837 secs]
[Full GC (Allocation Failure)  2400838K->1024K(255488K), 0.0863236 secs]
add new element 14
add new element 15
...
(and counting)

Much better.

Answer 2

The other answer is indeed correct, I edited mine. As a small addendum, G1GC will not exhibit this behavior, unlike ParallelGC; which is the default under java-8.

What do you think will happen if I slightly change your program to (run under jdk-8 with -Xmx20m)

public static void main(String[] args) throws InterruptedException {
    WeakHashMap<String, int[]> hm = new WeakHashMap<>();
    int i = 0;
    while (true) {
        Thread.sleep(200);
        i++;
        String key = "" + i;
        System.out.println(String.format("add new element %d", i));
        hm.put(key, new int[512 * 1024 * 1]); // <--- allocate 1/2 MB
    }
}

It will work just fine. Why is that? Because it gives your program just enough breathing room for new allocations to happen, before WeakHashMap clears its entries. And the other answer already explains how that happens.

Now, in G1GC, things would be a bit different. When such a big object is allocated (more than 1/2 a MB usually), this would be called a humongous allocation. When that happens a concurrent GC will be triggered. As part of that cycle: a young collection will be triggered and a Cleanup phase will be initiated that will take care of posting the event to the ReferenceQueue, so that WeakHashMap clears its entries.

So for this code:

public static void main(String[] args) throws InterruptedException {
    Map<String, int[]> hm = new WeakHashMap<>();
    int i = 0;
    while (true) {
        Thread.sleep(1000);
        i++;
        String key = "" + i;
        System.out.println(String.format("add new element %d", i));
        hm.put(key, new int[1024 * 1024 * 1]); // <--- 1 MB allocation
    }
}

that I run with jdk-13 (where G1GC is the default)

java -Xmx20m "-Xlog:gc*=debug" gc.WeakHashMapTest

Here is a portion of the logs:

[2.082s][debug][gc,ergo] Request concurrent cycle initiation (requested by GC cause). GC cause: G1 Humongous Allocation

This already does something different. It starts a concurrent cycle (done while your application is running), because there was a G1 Humongous Allocation. As part of this concurrent cycle it does a young GC cycle (that stops your application while running)

 [2.082s][info ][gc,start] GC(0) Pause Young (Concurrent Start) (G1 Humongous Allocation)

As part of that young GC, it also clears humongous regions, here is the defect.

---

You can now see that jdk-13 does not wait for garbage to pile up in the old region when really big objects are allocated, but triggers a concurrent GC cycle, that saved the day; unlike jdk-8.

You might want to read what DisableExplicitGC and/or ExplicitGCInvokesConcurrent mean, coupled with System.gc and understand why calling System.gc actually helps here.