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
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.