23
votes

What does "Full GC (System)" entry in the garbage collection logs mean? That some class called System.gc() ?

My garbage collection logs has two different entry types for 'full gc'? One with the word 'System', the other without. What's the difference?

(Update: I searched on this term and didn't find a definitive answer, only a few questions. So I thought I'd post it).

System:

164638.058: [Full GC (System) [PSYoungGen: 22789K->0K(992448K)] [PSOldGen: 1645508K->1666990K(2097152K)] 1668298K->1666990K(3089600K) [PSPermGen: 164914K->164914K(166720K)], 5.7499132 secs] [Times: user=5.69 sys=0.06, real=5.75 secs]

No-System:

166687.013: [Full GC [PSYoungGen: 126501K->0K(922048K)] [PSOldGen: 2063794K->1598637K(2097152K)] 2190295K->1598637K(3019200K) [PSPermGen: 165840K->164249K(166016K)], 6.8204928 secs] [Times: user=6.80 sys=0.02, real=6.81 secs]

GC Options

Our gc-related java memory options are: -Xloggc:../server/pe/log/jvm_gc.log -XX:+PrintGCTimeStamps -XX:+PrintGCDetails

We do not '-XX:+DisableExplicitGC', so it's possible some errant class does call System.gc()

fwiw, our full jvm options:

-Xms3072m -Xmx3072m -XX:+HeapDumpOnOutOfMemoryError -XX:-UseGCOverheadLimit -Xloggc:../server/pe/log/jvm_gc.log -XX:+PrintGCTimeStamps -XX:+PrintGCDetails -XX:MaxPermSize=256m -XX:+UseCompressedOops

thanks in advance,

will

2

2 Answers

16
votes

From the source for OpenJDK I would say it is

const bool is_system_gc = gc_cause == GCCause::_java_lang_system_gc;

// This is useful for debugging but don't change the output the
// the customer sees.
const char* gc_cause_str = "Full GC";
if (is_system_gc && PrintGCDetails) {
  gc_cause_str = "Full GC (System)";
}

I created a custom version of the Runtime class to record the thread name and stack trace to a file whenever Runtime.getRuntime().gc() was called. (System.gc() calls this) I found it useful in tracking down and removing such callers.

One place this happens is in sun.misc.GC class. The RMI will ask this class to ensure a GC has been performing in the last N seconds. If there has been no GC it triggers a full GC.

This only shows as a problem if you reduce the number of minor GCs. Ironicly it can mean you get more full GCs. ;)

I don't use RMI (except perhaps JConsole) So I have it set to a week. (Think the default is an hour)

-Dsun.rmi.dgc.server.gcInterval=604800000
-Dsun.rmi.dgc.client.gcInterval=604800000
1
votes

I test explicit GC on my mac, it do show "Full GC (System)" when using jdk 1.6, but show "Full GC" with jdk 1.7

So don't rely on the "System" label when you tuning GC log unless you know exactly about running environment and jdk version number