8i | 9i | 10g | 11g | 12c | 13c | 18c | 19c | 21c | 23c | Misc | PL/SQL | SQL | RAC | WebLogic | Linux
Monitoring Java Garbage Collection Using jstat
This article provides a very brief introduction to diagnosing Java performance problems relating to garbage collection. For more details consider reading this article.
The Problem
It can be quite difficult to diagnose performance problems with the JVM. In many cases, bad performance comes down to the way garbage collection is happening inside the JVM. I had an example of this while using Tomcat, which I will use to describe how to diagnose garbage collection issues.
Looking at the server, it was pretty quiet overall, but the tomcat process is hitting one core on the server very hard.
$ top top - 15:52:21 up 104 days, 4:06, 1 user, load average: 1.30, 1.20, 1.13 Tasks: 403 total, 1 running, 402 sleeping, 0 stopped, 0 zombie Cpu(s): 4.2%us, 0.0%sy, 0.0%ni, 94.7%id, 1.0%wa, 0.0%hi, 0.2%si, 0.0%st Mem: 74180940k total, 31597888k used, 42583052k free, 2027308k buffers Swap: 25853944k total, 0k used, 25853944k free, 21455252k cached PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 10263 tomcat 19 0 3475m 2.9g 25m S 99.6 4.1 1407:07 java 5640 root 10 -5 0 0 0 S 0.7 0.0 83:29.19 kjournald 11097 tomcat 15 0 13020 1360 820 R 0.3 0.0 0:00.30 top 1 root 15 0 10364 636 544 S 0.0 0.0 0:05.26 init 2 root RT -5 0 0 0 S 0.0 0.0 1:23.84 migration/0 3 root 34 19 0 0 0 S 0.0 0.0 0:00.13 ksoftirqd/0 4 root RT -5 0 0 0 S 0.0 0.0 0:00.00 watchdog/0
Using jstat
The jstat utility is part of the JDK, so it is available in any Java environment. You can get details about the jstat command line parameters here (Java 6, Java 7).
Checking the associated Java process (PID: 10263) using jstat and the "-gccause" option, we can see it is garbage collecting continuously.
$ ./jstat -gccause 10263 2000 S0 S1 E O P YGC YGCT FGC FGCT GCT LGCC GCC 0.00 0.00 100.00 100.00 78.90 43056 782.341 7931 29130.708 29913.049 Allocation Failure unknown GCCause 0.00 0.00 100.00 100.00 78.90 43056 782.341 7931 29130.708 29913.049 Allocation Failure unknown GCCause 0.00 0.00 70.54 100.00 78.90 43056 782.341 7931 29134.423 29916.764 unknown GCCause No GC 0.00 0.00 99.48 100.00 78.90 43056 782.341 7932 29134.423 29916.764 Allocation Failure unknown GCCause 0.00 0.00 99.48 100.00 78.90 43056 782.341 7932 29134.423 29916.764 Allocation Failure unknown GCCause 0.00 0.00 100.00 99.88 78.90 43056 782.341 7933 29138.241 29920.582 Allocation Failure unknown GCCause 0.00 0.00 100.00 99.88 78.90 43056 782.341 7933 29138.241 29920.582 Allocation Failure unknown GCCause 0.00 0.00 99.85 99.88 78.91 43056 782.341 7934 29141.941 29924.282 Allocation Failure unknown GCCause $
The "Allocation Failure" message suggests there has been a request for memory, which has failed because the heap is full, which results in garbage collection kicking in to free up some memory to allow the allocation to work.
The fact the Java process is taking 100% of the CPU core, most of which is being used for garbage collection suggests this is worth focusing on.
Solutions
If a Java process is spending most of its time garbage collecting, then it is not doing any real work for us, which is a problem. How can we solve this? There are a few options that may help.
Increase the Java heap size: If you allocate more memory to the Java process, it will take longer for the heap to fill up, so it will take longer before the garbage collector has to kick in. The "-Xms" and "-Xmx" memory options determine the starting and maximum heap sizes respectively. Consider increasing their size. It is recommended that they are set to the same value.
MEM_OPTIONS="-Xms4096M –Xmx4096M"
Of course, once the heap is full, you are still going to need garbage collection eventually, and that collection may take a long time, causing the process to appear to hang. This solution on its own is likely to cause bigger problems in the long run.
Limit the size for cached classes: Caching classes is a good thing, but it can take up a lot of room. The "-XX:PermSize" and "-XX:MaxPermSize" memory options determine the starting and maximum heap sizes for caching objects.
MEM_OPTIONS="-Xms4096M –Xmx4096M -XX:PermSize=512m -XX:MaxPermSize=512m"
Enable incremental garbage collection: In Java 6 onward it is recommended to use incremental garbage collection. This allows the JVM to clean up as it goes, which reduces the chances of large garbage collections causing the process to hang for a time. You can enable incremental garbage collection using the "-XX:+UseConcMarkSweepGC -XX:+CMSIncrementalMode" memory options.
MEM_OPTIONS="-Xms4096M -Xmx4096M -XX:PermSize=512m -XX:MaxPermSize=512m -XX:+UseConcMarkSweepGC -XX:+CMSIncrementalMode"
The "-XX:+PrintGCDetails -XX:+PrintGCTimeStamps" options allow garbage collection trace information to be written to stdout, which will get pushed to your log file, so this is very helpful in diagnosing garbage collection performance problems.
MEM_OPTIONS="-Xms4096M -Xmx4096M -XX:PermSize=512m -XX:MaxPermSize=512m -XX:+UseConcMarkSweepGC -XX:+CMSIncrementalMode -XX:+PrintGCDetails -XX:+PrintGCTimeStamps"
The "-XX:+UseCompressedOops" option reduces the memory required for Ordinary Object Pointers in 64-bit JVMs, so this may help save some space.
MEM_OPTIONS="-Xms4096M -Xmx4096M -XX:PermSize=512m -XX:MaxPermSize=512m -XX:+UseConcMarkSweepGC -XX:+CMSIncrementalMode -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+UseCompressedOops"
If you continue to get issues, you might want to consider limiting young generation with "-XX:NewSize" and "-XX:MaxNewSize", which will force garbage collection to kick in more frequently, resulting in smaller garbage collecting events.
MEM_OPTIONS="-Xms4096M -Xmx4096M -XX:PermSize=512m -XX:MaxPermSize=512m -XX:+UseConcMarkSweepGC -XX:+CMSIncrementalMode -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+UseCompressedOops -XX:NewSize=200m -XX:MaxNewSize=200m"
As I mentioned at the start of the article, this is a very brief introduction to the subject. This should be a stepping stone to something like this article.
For more information see:
- jstat - Java Virtual Machine Statistics Monitoring Tool (Java 6)
- jstat - Java Virtual Machine Statistics Monitoring Tool (Java 7)
- Java SE 6 HotSpot Virtual Machine Garbage Collection Tuning
Hope this helps. Regards Tim...