Let’s pick up the one single log statement and examine each field in it:

2014-11-18T16:39:37.728-0800 – Time stamp at which GC ran

Full GC – Type of GC. It could be either ‘Full GC’ or ‘GC’

[PSYoungGen: 116544K->12164K(233024K)] – After GC ran young generation space came down from 116544k (i.e. 113mb) to 12164k (i.e. 12mb). Total allocated young generation space is 233024k (i.e.227mb)

[PSOldGen: 684832K->699071K(699072K)] – After GC ran old generation space came down from 684832k (i.e. 669mb) to 699071k (i.e. 682mb). Total allocated old generation space is 669072k (i.e. 682mb)

801376K->711236K(932096K) – After GC run overall memory came down from. Total allocated memory space is 932096k (i.e.910mb)

[PSPermGen: 2379K->2379K(21248K)] – After GC ran there was no drop in perm generation space

3.4230220 secs – GC took 3.42 seconds to complete

[Times: user=3.40 sys=0.02, real=3.42 secs] – Real is wall clock time – time from start to finish of the call. This is all elapsed time including time slices used by other processes and time the process spends blocked (for example if it is waiting for I/O to complete).

User is the amount of CPU time spent in user-mode code (outside the kernel) within the process. This is only actual CPU time used in executing the process. Other processes and time the process spends blocked do not count towards this figure.

Sys is the amount of CPU time spent in the kernel within the process. This means executing CPU time spent in system calls within the kernel, as opposed to library code, which is still running in user-space. Like ‘user’, this is only CPU time used by the process.

In your case if the CPU time (3.4 sec) is considerably higher than the real time passed (3.42 Sec), we can conclude that the GC was run using multiple threads.

Fig: Anatomy of Garbage Collection Log Statement. Click to enlarge

Tool to analyze GC Logs

It’s tedious to analyze GC logs in a text editor. HP JMeter is a great tool to analyze GC log files. Here is my article to walk you through HP Jmeter