JVM Memory Management
&
Diagnostics
Dhaval P Shah
Ground Rules & Disclaimer !
JVM Memories
OS Memory
Java Process Memory
Java Object Heap Native Memory
Young Old Metaspace
-Xmn -XX:MetaspaceSize
-Xmx
Detailed – Young Generation
Young
Survivor Space
Eden S0 S1
TLAB 1 TLAB 2 TLAB 3 Common Area
The GC taxonomy
• Minor GC
• Major GC
• Full GC
Understanding
Java Garbage
Collector
How GC works – Step 1
How GC works – Step 2
How GC works – Step 3
How GC works – Step 9
Garbage Collectors
Young Tenured JVM Option
Incremental Incremental -Xincgc
Serial Serial -XX:+UseSerialGC
Parallel Scavenge Serial -XX:+UseParallelGC
-XX:+UseParallelOldGC
Prallel New Serial N/A
Serial Parallel Old N/A
Parallel Scavenge Parallel Old -XX:+UseParallelGC
-XX:+UseParallelOldGC
Parallel New Parallel Old N/A
Serial CMS -XX:-UseParNewGC
-XX:+UseConcMarkSweepGC
Parallel Scavenge CMS N/A
Parallel New CMS -XX:+UseParNewGC
-XX:+UseConcMarkSweepGC
G1 G1 -XX:+UseG1GC
Serial Vs Parallel Vs CMS
Initial Mark
Marking / Pre cleaning
Remark
Sweeping / Reset
Serial GC Parallel GC CMS GC
Application Threads
Stop the world (STW) GC Threads
GC Threads
Diagnostic Data
• GC Logs
• Heap usage details
• GC pauses
• Help in appropriate configuration of memory pools
• Heap Dumps
• Unexpected memory growth and memory leaks
• Heap Histograms
• Quick view of the heap to understand what is growing
• Java Flight Recordings
• Unexpected memory growth and memory leaks
• GC Events
Understanding
GC logs
Major – Parallel GC Logs
2015-05-26T14:45:37.987-02001:151.1262:[Full GC3(Ergonomics 4)[PSYoung:1305132K-
>0K(2796544K)]5 [ParOldGen6 : 7133794K->6597672K7(8388608K)8] 8438926K->6597672K9
11185152K10,[Metaspace:6745K->6745K(1056768K)]11,0.9158801 secs12[Times: user=4.49 sys=0.64,
real=0.92 secs]13
1. 2015-05-26T14:27:41.155-0200 – Time when the GC event started
2. 151.126 – Time when the GC event started, relative to the JVM startup time. Measured in seconds.
3. Full GC – Flag indicating that the event is Full GC event cleaning both the Young and Old generations
4. Ergonomics – This indicates that the JVM internal ergonomics decided this is the right time to collect some
garbage.
5. [PSYoungGen: 1305132K->0K(2796544K)] – Indicates a parallel mark-copy stop-the world garbage collector
named “PSYoungGen” was used to clean the Young Generation. Usage of Young Generation shrank from 1305132K
to 0, since after a Full GC the Young Generation is often left completely empty
6. ParOldGen – Type of the collector used to clean the Old Generation. In this case, parallel mark-sweep compact
stop-the-world garbage collector named ParOldGen was used
Major – Parallel GC Logs [Contd.]
2015-05-26T14:45:37.987-02001 :151.1262 :[Full GC3 (Ergonomics 4)[PSYoung:1305132K-
>0K(2796544K)]5 [ParOldGen6 : 7133794K->6597672K7 (8388608K)8 ] 8438926K->6597672K9
11185152K10 ,[Metaspace:6745K->6745K(1056768K)]11 ,0.9158801 secs12 [Times: user=4.49
sys=0.64, real=0.92 secs]13
7. 7133794K->6597672K – Usage of the Old Generation before and after the collection
8. (8388608K) – Total size of the Old Generation
9. 8438926K->6597672K – Usage of the whole heap before and after the collection.
10. (11185152K) – Total heap available
11. [Metaspace: 6745K->6745K(1056768K)] – Similar information about Metaspace region. As we can see, no
garbage was collected in Metaspace during this event
12. 0.9158801 secs – Duration of the GC event in seconds
13. [Times: user=4.49 sys=0.64, real=0.92 secs] – Duration of the GC event, measured in different categories:
• user – Total CPU time that was consumed by Garbage Collector threads during this collection
• sys – Time spent in OS calls or waiting for system event
• real – Clock time for which your application was stopped. With Parallel GC this number should be close to (user time + system
time) divided by the number of threads used by Garbage Collector. In this particular case 8 threads were used. Note that due to
some activities not being parallelizable, it always exceeds the ratio by a certain amount.
GC Performance Tuning
Throughput G1 GC Latency
Maximizer Sensitive
Parallel GC CMS GC
Ramifications of Allocation Rate
Alloc. Rate 2nd GC =
(38,368 – 5,088) /
(446 – 291)
JVM Flags –
-XX:NewSize
-XX:MaxNewSize
-XX:NewRatio
-XX:SurvivorRatio
Ramifications of Promotion Rate
Young =
(33,280 – 5,088)
Total = (33,280 –
24,360)
Promotion Rate 1st GC=
(Young – Total) / Time
JVM Flag –
-
XX:MaxTenuringThr
eshold
Ramifications of Object Copy
Taming the GC
Reducing Allocation Failures !
GC Log Properties With Default GC algorithm After changing GC algorithm to CMS
Throughput 99.563 % 99.714 %
Latency - Avg Pause Time 0.097 sec 0.053 sec
Latency – Max Pause GC Time 2.870 sec 0.440 sec
Allocation Failure Time : 89.93% Time : 49.52 %
CMS GC – The Performance Degrader !
GC Log Properties With CMS as GC algorithm UseCMSInitiatingOccupancyOnly = true,
CMSInitiatingOccupancyFraction = 70,
-XX:ParallelGCThreads = 8
Old Generation - Allocated 2.67 GB 2.67 GB
Old Generation - Peak 2.67 GB 1.24 GB
Throughput 96.966 % 99.49 %
Latency – Avg Pause GC Time 574 ms 87 ms
Latency – Max Pause GC Time 17 sec 0.73 sec
Duration (sec) No. of GCs Percentage Duration (sec) No. of GCs Percentage
0-2 11508 97.547 0 – 0.1 11508 95.573
2-4 1 0 0.1 – 0.2 194 1.61
6-8 44 0.14 0.2 - 0.3 69 0.57
8 - 10 375 1.19 0.3 – 0.4 181 1.5
10 - 12 286 0.9 0.4 – 0.5 85 0.71
12 - 14 69 0.22 0.5 – 0.6 3 0.02
16 - 18 1 0 0.7 – 0.8 1 0.01
Closing Notes . . .
• GC - an important aspect of application from Performance standpoint
• Key JVM flags
o -XX:+UseCMSInitiatingOccupancyOnly=<Boolean flag>
o -XX:CMSInitiatingOccupancyFraction=<Percent>
o -XX:ParallelGCThreads=<N>
o -XX:+MaxTenuringThreshold =<N>
o -XX:+ScavengeBeforeFullGC
o -XX:+CMSScavengeBeforeRemark
o -XX:NewRatio=<N>
Note – Above flags wont be applicable to G1 GC !
