Oracle 8i | Oracle 9i | Oracle 10g | Oracle 11g | Oracle 12c | Miscellaneous | PL/SQL | SQL | Oracle RAC | Oracle Apps | 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.

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:

Hope this helps. Regards Tim...

Back to the Top.