Analysing Java Garbage Collector

Application Phases: Initialization → Steady state → Summary (optional)
– Initialization: startup, lots of allocations
– Steady state: where application spends the most time, running the ‘core’ part of the application
– Summary: produce report of what has happen, might be computationally intensive and maybe has lots of allocation as well
Note: Typically, the steady state is the most important

Performance
Three important performance attributes are throughput, latency, footprint
– Throughput – the percentage of time not spent on GC
– Latencies – the time when an app appears unresponsive because of GC
– Footprint – memory size
Note: Not all three are always important
– Usually select two of the three
– But you need to know what is important for your application

GC Logging
Yes even in production
– Very important, not just for testing, minimal overhead

Correlate application-level with GC/JVM level events
– GC not always to blame for long pauses
– Capture time/context sensitive events that might not be able to reproduce under testing

Flags

– -XX:+PrintGCTimeStamps -XX:+PrintGCDetails -Xloggc:<file>
– -XX:+PrintGCDateStamps (from JDK6u4)
– -XX:+PrintHeapAtGC

GC Logging Output – 1

-XX:+PrintGCTimeStamps -XX:+PrintGCDetails
27.199: [Full GC (System)
[PSYoungGen: 81K->0K(26304K)]
[PSOldGen: 7497K->7559K(32256K)] 7579K->7559K(58560K)
[PSPermGen: 12166K-&gt;12166K(16384K)], <i>0.0495600 secs</i>]
[Times: user=<i>0.05 </i>sys=0.00, real=<i>0.04 secs</i>]
28.503: [GC
[PSYoungGen: 869K-&gt;64K(26304K)] 8429K-&gt;7623K(58560K),
0.0008190 secs]
[Times: user=0.00 sys=0.00, real=0.00 secs]

GC Logging Output – 2

-XX:+PrintGCDateStamps -XX:+PrintGCDetails
2011-04-25T10:55:50.007+0800: 9.140:
[GC [PSYoungGen: 8024K->1530K(26304K)] 15470K->10427K(58560K),
0.0023450 secs]
[Times: user=0.00 sys=0.00, real=0.01 secs]
2011-04-25T10:55:50.009+0800: 9.143:
[Full GC (System) [PSYoungGen: 1530K->0K(26304K)]
[PSOldGen: 8896K->7135K(32256K)] 10427K->7135K(58560K)
[PSPermGen: 11640K->11631K(23808K)], 0.0778080 secs]
[Times: user=0.12 sys=0.00, real=0.07 secs]

GC Logging Output – 3

-XX:+PrintGCHeapAtGC -Xloggc:<file>
{<b>Heap before GC invocations=20 (full 8)</b>:
PSYoungGen total 14144K, used 2287K [0xa3b90000, 0xa4b50000, 0xb3790000)
eden space 12160K, 18% used [0xa3b90000,0xa3dcbe00,0xa4770000)
from space 1984K, 0% used [0xa4770000,0xa4770000,0xa4960000)
to space 1984K, 0% used [0xa4960000,0xa4960000,0xa4b50000)
PSOldGen total 32256K, used 7465K [0x84390000, 0x86310000, 0xa3b90000)
object space 32256K, 23% used [0x84390000,0x84ada710,0x86310000)
PSPermGen total 19968K, used 11994K [0x80390000, 0x81710000, 0x84390000)
object space 19968K, 60% used [0x80390000,0x80f46bb0,0x81710000)
45.215: [GC 9753K-&gt;7538K(46400K), 0.0006110 secs]

Heap after GC invocations=20 (full 8):

PSYoungGen total 14144K, used 72K [0xa3b90000, 0xa4b50000, 0xb3790000)
eden space 12160K, 0% used [0xa3b90000,0xa3b90000,0xa4770000)
from space 1984K, 3% used [0xa4960000,0xa49723b0,0xa4b50000)
to space 1984K, 0% used [0xa4770000,0xa4770000,0xa4960000)
PSOldGen total 32256K, used 7465K [0x84390000, 0x86310000, 0xa3b90000)
object space 32256K, 23% used [0x84390000,0x84ada710,0x86310000)
PSPermGen total 19968K, used 11994K [0x80390000, 0x81710000, 0x84390000)
object space 19968K, 60% used [0x80390000,0x80f46bb0,0x81710000)
}

Choice of JVM
32-bit
– -d32 (default)
– For heap size up to 2.5G/3G

64-bit with/without compressed references
– -d64, -XX:+UseCompressedOops
– For heap size up to 26G or unlimited

32-bit to 64-bit migration
– Higher heap size requirement (approx 20%)
– Throughput impact (up to 20%, without compressed refs)