Reputation: 91
I'm using the Oracle 1.7.0_10 VM for a high performance Java app that I'm running. I've spent a lot of time with the HPROF profiler looking at memory allocation because it was doing a ton of GC (as measured by -verbose:gc output). Now, I'm doing very little allocation, but the GC still runs quite often, does very little work, and takes a long time. For example, here's some output I got using no special GC options (-verbose:gc -XX:+PrintGCDetails -Xmx4g
):
[GC [PSYoungGen: 21197K->96K(1228224K)] 420220K->399118K(2045440K), 0.0081950 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
[Full GC (System) [PSYoungGen: 96K->0K(1228224K)] [ParOldGen: 399022K->394779K(817216K)] 399118K->394779K(2045440K) [PSPermGen: 10758K->10758K(21248K)], 0.1503380 secs] [Times: user=0.89 sys=0.00, real=0.15 secs]
[GC [PSYoungGen: 21195K->128K(1238592K)] 415974K->394907K(2055808K), 0.0061850 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
[Full GC (System) [PSYoungGen: 128K->0K(1238592K)] [ParOldGen: 394779K->394779K(817216K)] 394907K->394779K(2055808K) [PSPermGen: 10758K->10758K(21248K)], 0.2534350 secs] [Times: user=1.71 sys=0.01, real=0.25 secs]
These general messages repeat 10 times during a 2.5 second wall time - based on their timings of roughly 250ms, this is all the process seems to be doing during that time (I understand it might be doing work on another thread for some of it). What confuses me, is that it doesn't seem like there's much work going on. Looking at the messages, all of the generations seem to have plenty of space - Young goes for 21Mb->0 but it has 1.2G allocated and Old generations barely change in size and are well below their thresholds.
Given this, why does the GC keep running so often? And it doesn't seem like there's anyway it should take 250ms on a core i7 with nothing else running to clean up so little memory.
I've tried other GC parameters, but none seem to have an impact. Unfortunately, I can't run in any other VMs since my app uses 1.7 specific features.
Upvotes: 2
Views: 487
Reputation: 500367
Given this, why does the GC keep running so often?
"Full GC (System)" normally indicates that your application has explicitly asked for the garbage collector to be run, by calling Runtime.getRuntime().gc()
or System.gc()
.
You therefore might want to double-check your code.
Also, see Does java garbage collection log entry "Full GC (System)" mean some class called System.gc()?
Upvotes: 6