GC Log Analysis

The main parameters of jvm gc logs include:

-XX: + printgc: Output GC logs

-XX: + printgcdetails: Output detailed GC logs

-XX: + printgctimestamps: output the GC timestamp (in the form of reference time)

-XX: + printgcdatestamps: output the GC timestamp (in the form of a date, for example, 2013-05-04t21: 53: 59.234 + 0800)

-XX: + printheapatgc prints heap information before and after GC.

-Xloggc: Output path of the ../logs/GC. log file

After I make the following settings

-XX:+PrintGCDetails -Xloggc:../logs/gc.log -XX:+PrintGCTimeStamps 

The following logs will be printed:

0.756: [Full GC (System) 0.756: [CMS: 0K->1696K(204800K), 0.0347096 secs] 11488K->1696K(252608K), [CMS Perm : 10328K->10320K(131072K)], 0.0347949 secs] [Times: user=0.06 sys=0.00, real=0.05 secs]  1.728: [GC 1.728: [ParNew: 38272K->2323K(47808K), 0.0092276 secs] 39968K->4019K(252608K), 0.0093169 secs] [Times: user=0.01 sys=0.00, real=0.00 secs]  2.642: [GC 2.643: [ParNew: 40595K->3685K(47808K), 0.0075343 secs] 42291K->5381K(252608K), 0.0075972 secs] [Times: user=0.03 sys=0.00, real=0.02 secs]  4.349: [GC 4.349: [ParNew: 41957K->5024K(47808K), 0.0106558 secs] 43653K->6720K(252608K), 0.0107390 secs] [Times: user=0.03 sys=0.00, real=0.02 secs]  5.617: [GC 5.617: [ParNew: 43296K->7006K(47808K), 0.0136826 secs] 44992K->8702K(252608K), 0.0137904 secs] [Times: user=0.03 sys=0.00, real=0.02 secs]  7.429: [GC 7.429: [ParNew: 45278K->6723K(47808K), 0.0251993 secs] 46974K->10551K(252608K), 0.0252421 secs]  

 

Let's take the second to last record and analyze what each field represents.

5.617 (timestamp): [GC (Young GC) 5.617 (timestamp): [parnew (use parnew as the garbage return period of the young generation ): 43296 K (size before garbage collection by the young generation)-> 7006 K (size after garbage collection by the young generation) (47808 K) (total size of the young generation ), 0.0136826 secs (recycling time)] 44992 K (size before garbage collection in the heap area)-> 8702 K (size after garbage collection in the heap Area) (252608 K) (Total heap size), 0.0137904 secs (recovery time)] [times: User = 0.03 (Young GC user time consumed) sys = 0.00 (Young GC system time consumed ), real = 0.02 secs (actual time consumed by young GC)]

 

Let's make a simple analysis of the data.

From the last GC record, we can see that young GC recycles45278-6723 = 38555 KMemory

The total number of heap zones is reduced through this collection.46974-10551 = 36423 KMemory.

38555-36423 = 2132 KThis time, the memory with KB of young GC is moved to the Old Gen,

 

Let's verify it.

The size of the Old Gen before the last young GC is8702-7006 = 1696

After recycling, the Old Gen memory usage is10551-6723 = 3828

The Old Gen memory increases after this young GC.3828-1696 = 2132 KConsistent with the expected

 

Reset GC log output

 

-XX:+PrintGCDetails  -XX:+PrintHeapAtGC  -XX:+PrintGCDateStamps  -XX:+PrintTenuringDistribution  -verbose:gc  -Xloggc:gc.log  

Then you can see the heap memory information before and after GC.

{Heap before GC invocations=1 (full 0):   PSYoungGen      total 152896K, used 131072K [0x00000000f5560000, 0x0000000100000000, 0x0000000100000000)    eden space 131072K, 100% used [0x00000000f5560000,0x00000000fd560000,0x00000000fd560000)    from space 21824K, 0% used [0x00000000feab0000,0x00000000feab0000,0x0000000100000000)    to   space 21824K, 0% used [0x00000000fd560000,0x00000000fd560000,0x00000000feab0000)   PSOldGen        total 349568K, used 0K [0x00000000e0000000, 0x00000000f5560000, 0x00000000f5560000)    object space 349568K, 0% used [0x00000000e0000000,0x00000000e0000000,0x00000000f5560000)   PSPermGen       total 26432K, used 26393K [0x00000000d0000000, 0x00000000d19d0000, 0x00000000e0000000)    object space 26432K, 99% used [0x00000000d0000000,0x00000000d19c64a0,0x00000000d19d0000)  2013-05-05T23:16:10.480+0800: 5.228: [GC  Desired survivor size 22347776 bytes, new threshold 7 (max 15)   [PSYoungGen: 131072K->8319K(152896K)] 131072K->8319K(502464K), 0.0176346 secs] [Times: user=0.03 sys=0.00, real=0.02 secs]   Heap after GC invocations=1 (full 0):   PSYoungGen      total 152896K, used 8319K [0x00000000f5560000, 0x0000000100000000, 0x0000000100000000)    eden space 131072K, 0% used [0x00000000f5560000,0x00000000f5560000,0x00000000fd560000)    from space 21824K, 38% used [0x00000000fd560000,0x00000000fdd7ff78,0x00000000feab0000)    to   space 21824K, 0% used [0x00000000feab0000,0x00000000feab0000,0x0000000100000000)   PSOldGen        total 349568K, used 0K [0x00000000e0000000, 0x00000000f5560000, 0x00000000f5560000)    object space 349568K, 0% used [0x00000000e0000000,0x00000000e0000000,0x00000000f5560000)   PSPermGen       total 26432K, used 26393K [0x00000000d0000000, 0x00000000d19d0000, 0x00000000e0000000)    object space 26432K, 99% used [0x00000000d0000000,0x00000000d19c64a0,0x00000000d19d0000)  } 

[0x00000000f5560000,0x00000000f5560000,0x00000000fd560000) 

Logs in this form have two meanings:
When such logs appear in the details of generation, the three numbers are called low_boundary, high, and high_boundary In the hotspot.
Low_boundary: the lowest address boundary of the reserved space. It is usually equal to "low", which is the lowest address boundary of the commited space.
High: Maximum address boundary of commited Space
High_boundary: the highest address boundary of the reserved space.

[Low_boundary, high_boundary) is the reserved space, and the size of this space is max capacity.
[Low, high) is the commited space, and the size of this space is the current capacity (capacity.
Capacity may fluctuate between the minimum and maximum values of a pair. The maximum value is the max capacity mentioned above.

Address: http://swcdxd.iteye.com/blog/1859858