30

70.222: [GC [PSYoungGen: 131072K->15437K(152896K)] 131072K->15509K(502464K), 0.0228420 secs] [Times: user=0.09 sys=0.01, real=0.02 secs]

luka5z
  • 7,525
  • 6
  • 29
  • 52
GKP
  • 1,057
  • 1
  • 11
  • 24

2 Answers2

37

You can find tutorials on interpreting verbose GC output eg. in:

Looking at verbosegc output tutorial - Java 7, you can see YoungGen space analysis:

UPDATE 03/27/2014: The "Collection time (secs)" is actually a Timestamp showing the when the GC occurred. The Collection times are reported as Times=user=0.45 sys=0.01, real=0.14 secs].

enter image description here

Here, the 262208K->137900K(100428K) means Java Heap before GC-> Java Heap after GC (Total Size of the Java Heap).

And, OldGen space analysis:

enter image description here

Aleš
  • 8,896
  • 8
  • 62
  • 107
  • So you are saying that 131072K (young gen before)->15437K (young gen after)(152896K)] 131072K (java heap before)->15509K(502464K) (java heap after), ??? Is my understanding correct ? – GKP May 28 '13 at 18:49
  • 1
    The number on the left is not the collection time. But, it's the timestamp representing the time since java process is running. – Arnab Biswas Mar 27 '14 at 11:05
  • You are correct, wow, there is a mistake. Timestamp is so essential to me that I did not check it in that picture... will put an update there. – Aleš Mar 27 '14 at 15:02
  • Thanks, I cannot upgrade the diagram so I have added an explanation. – Aleš Mar 27 '14 at 16:58
  • 4
    Use -XX:+PrintGCDateStamps, you will get the actual time when the process is running rather than the time elasped. I find it more useful. – LearnToLive May 13 '15 at 15:45
  • Yep, that's correct! We switched all our GC logs to `-XX:+PrintGCDateStamps` – Aleš May 13 '15 at 18:17
14

In Addition to other answer , I am explaining Times section of log

[Times: user=0.09 sys=0.01, real=0.02 secs]

The “Times” section of the detailed log contains information about the CPU time used by the GC, separated into user space (“user”) and kernel space (“sys”) of the operating system.Also, it shows the real time (“real”) that passed while the GC was running.

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

Detailed Example

Vipin
  • 4,851
  • 3
  • 35
  • 65