24

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

user331465
  • 2,984
  • 13
  • 47
  • 77

2 Answers2

16

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
Peter Lawrey
  • 525,659
  • 79
  • 751
  • 1,130
  • _java_lang_system_gc looks suspiciously close to java.lang.System.gc(). ""Just making it plain". – user331465 Jul 08 '11 at 15:56
  • Without reading all the code, I would say its a safe bet. I have added to my answer to say how to detect what is triggering this full GC and what might be your cause and how to fix it. – Peter Lawrey Jul 08 '11 at 15:57
2

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

user922965
  • 135
  • 1
  • 6