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

what jdk version? do you use any -Xms and -Xmx parameters? on which step you got OOM? — Vladislav Kysliy, Mar 08 '20 at 10:19
I can't reproduce this on my system. In debug mode I can see that the GC is doing it's job. Can you check in debug mode if the Map is actually beeing cleared or not? — magicmn, Mar 08 '20 at 10:39
jre 1.8.0_212-b10 -Xmx200m You can see more detail from gc log that I attached ; thx — Dominic Peng, Mar 08 '20 at 14:16

tentacle · Accepted Answer · 2020-03-08T13:06:32.067

8

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.

edited Mar 08 '20 at 13:06

answered Mar 08 '20 at 12:52

tentacle

543
1
3
8

Thx for your answer, seems your conclusion is correct; while i try to reduce the payload from 1024 * 10000 to 1024 * 1000; the code can work fine; but i STILL not very understand your explaination; as your meaning, if need to release space from WeakHashMap, should do gc two times at least; the frist time is to collect keys from map, and add them into reference queue; the second time is to collect values? but from the frist log that you provided, actually, JVM had already taken full gc two times; – Dominic Peng Mar 08 '20 at 15:18
You're saying, that "Map values are strongly reachable and are cleared by map itself when certain operations are invoked on it.". Where are they reachable from? – Andronicus Mar 08 '20 at 16:02
1

It will be not enough to just have two GC runs in your case. First you need one GC run, that's correct. But the next step will require some interaction with the map itself. What you should look for is method `java.util.WeakHashMap.expungeStaleEntries` which reads reference queue and removes entries from the map thus making values unreachable and subject to collection. Only after that is done second pass of GC will free up some memory. `expungeStaleEntries` is called in a number of cases like get/put/size or pretty much everything you usually do with a map. That's the catch. – tentacle Mar 08 '20 at 16:03
@Andronicus , map values are strongly reachable from within map itself via `java.util.WeakHashMap.Entry` instance. Don't get fooled by the fact that Entry extends WeakReference class. Map value is not a referent of this WeakReference instance but rather regular property field. The key is referent. – tentacle Mar 08 '20 at 16:23
@tentacle how should this map work then? If there is a strong reference to the value, then the entry cannot be garbage-collected. Do you know a good reference about that topic? – Andronicus Mar 08 '20 at 16:40
1

@Andronicus, this is by far the most confusing part of WeakHashMap. It was covered multiple times. https://stackoverflow.com/questions/5511279/what-is-a-weakhashmap-and-when-to-use-it – tentacle Mar 08 '20 at 16:53
2

@Andronicus [this answer](https://stackoverflow.com/a/50701443/2711488), especially the second half, might be helpful as well. Also [this Q&A](https://stackoverflow.com/q/54959146/2711488)… – Holger Mar 09 '20 at 11:03
@tentacle Thx for your answer; from your discussion, i think i understand your meaning; you had already explained your meaning clearly in frist statement; for WeakHashMap, the vaule still be strongly reachable by the instance that Map inside; GC cannot collect value, until wait for another operation to release this strongly reference; – Dominic Peng Mar 09 '20 at 14:27

Eugene · Answer 2 · 2020-03-09T13:25:40.963

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.

Java 8 doesn’t use G1GC by default. And the OP’s GC logs also clearly show that it is using parallel GC for the old generation. And for such a non-concurrent collector, it’s as simple as described in [this answer](https://stackoverflow.com/a/60587646/2711488) — Holger, Mar 09 '20 at 11:18
@Holger I was reviewing this answer today in the morning only to realize that it is indeed `ParalleGC`, I've edited and sorry (and thank you) for proving me wrong. — Eugene, Mar 09 '20 at 13:27
The “humongous allocation” still is a correct hint. With a non-concurrent collector, it implies that the first GC will run when the old generation is full, so the failure to reclaim enough space will make it fatal. In contrast, when you reduce the array size, a young GC will be triggered when there is still memory in the old generation left, so the collector can promote objects and continue. For a concurrent collector, on the other hand, it’s normal to trigger gc before the heap is exhausted, so `-XX:+UseG1GC` make it work in Java 8, just like `-XX:+UseParallelOldGC` makes it fail in new JVMs. — Holger, Mar 09 '20 at 13:46

OutOfMemoryException despite using WeakHashMap

2 Answers2

Linked