Reading verbosegc output

on waitingforcode.com

Reading verbosegc output

When you meet OutOfMemory or another error caused by the memory, you have some ways to debug. If you were persevering, you can use memory dump made with -XX:+HeapDumpOnOutOfMemoryError parameter. If you're even more persevering, you could see how Garbage Collector works thanks to two another JVM arguments: verbose and GC details printing.

At the begin of this article, we'll see what these two arguments make. In the next part, we'll focus on pragmatic approach by writing a sample class and analyzing the output generated by two GC arguments.

Garbage Collector verbosity

Let's start by explaining a little bit the first option - verbose. This option can take 3 arguments:

  • - gc: we'll focus on this argument in this article. The "gc" acronym means Garbage Collector. As you can deduce, we can analyze this argument's output to check Garbage Collector activity. It allows us to see how memory spaces changed with the program lifecycle. We'll analyze the output in the second part.
  • - class: this argument allows to verify which classes are loaded. Suppose that we have given very basic class:
    public class ClassVerbose {
    
      public static void main(String[] args) {
        List<String> myList = new ArrayList<String>();
        myList.add("A");
        myList.add("B");
    
        BigInteger bigOne = new BigInteger("553");
        System.out.println("BigInteger is "+bigOne);
    
        NormalClass nc = new NormalClass();
      }
    
    }
    
    class NormalClass {
    
    }
    

    To see which classes are loaded, you can just put -verbose:class argument into your run configuration and analyze the output. A sample output can be:

    [Loaded java.net.InetAddress from /usr/lib/jvm/java-7-openjdk-amd64/jre/lib/rt.jar]
    [Loaded java.nio.CharBuffer from /usr/lib/jvm/java-7-openjdk-amd64/jre/lib/rt.jar]
    [Loaded java.net.InetSocketAddress$InetSocketAddressHolder from /usr/lib/jvm/java-7-openjdk-amd64/jre/lib/rt.jar]
    [Loaded java.nio.HeapCharBuffer from /usr/lib/jvm/java-7-openjdk-amd64/jre/lib/rt.jar]
    [Loaded sun.security.action.GetBooleanAction from /usr/lib/jvm/java-7-openjdk-amd64/jre/lib/rt.jar]
    [Loaded java.nio.charset.CoderResult from /usr/lib/jvm/java-7-openjdk-amd64/jre/lib/rt.jar]
    [Loaded java.net.InetAddress$InetAddressHolder from /usr/lib/jvm/java-7-openjdk-amd64/jre/lib/rt.jar]
    [Loaded java.nio.charset.CoderResult$Cache from /usr/lib/jvm/java-7-openjdk-amd64/jre/lib/rt.jar]
    [Loaded java.nio.charset.CoderResult$1 from /usr/lib/jvm/java-7-openjdk-amd64/jre/lib/rt.jar]
    [Loaded java.nio.charset.CoderResult$2 from /usr/lib/jvm/java-7-openjdk-amd64/jre/lib/rt.jar]
    [Loaded java.net.InetAddress$Cache from /usr/lib/jvm/java-7-openjdk-amd64/jre/lib/rt.jar]
    [Loaded java.net.InetAddress$Cache$Type from /usr/lib/jvm/java-7-openjdk-amd64/jre/lib/rt.jar]
    BigInteger is 553
    [Loaded java.net.InetAddressImplFactory from /usr/lib/jvm/java-7-openjdk-amd64/jre/lib/rt.jar]
    [Loaded java.net.InetAddressImpl from /usr/lib/jvm/java-7-openjdk-amd64/jre/lib/rt.jar]
    [Loaded java.net.Inet6AddressImpl from /usr/lib/jvm/java-7-openjdk-amd64/jre/lib/rt.jar]
    [Loaded com.waitingforcode.verbose.NormalClass from file:/home/bartosz/tm/project/code/webapp/target/test-classes/]
    [Loaded sun.net.spi.nameservice.NameService from /usr/lib/jvm/java-7-openjdk-amd64/jre/lib/rt.jar]
    [Loaded java.net.InetAddress$1 from /usr/lib/jvm/java-7-openjdk-amd64/jre/lib/rt.jar]
    [Loaded java.lang.Shutdown from /usr/lib/jvm/java-7-openjdk-amd64/jre/lib/rt.jar]
    [Loaded java.lang.Shutdown$Lock from /usr/lib/jvm/java-7-openjdk-amd64/jre/lib/rt.jar]
    [Loaded java.net.Inet4AddressImpl from /usr/lib/jvm/java-7-openjdk-amd64/jre/lib/rt.jar]
    
  • - jni: the name of this parameter comes from Java Native Interface (JNI). As this name lets suppose, the verbose will print a trace every time when a native method (for example a code written in C) is resolved or registered with RegisterNative. To observe that, we can use again our ClassVerbose. But this time it will be run with -verbose:jni option. In the output we can observe (sun.misc.Unsafe contains a lot of native method, as you can see in its source code):
    [Registering JNI native method sun.misc.Unsafe.allocateMemory]
    [Registering JNI native method sun.misc.Unsafe.reallocateMemory]
    [Registering JNI native method sun.misc.Unsafe.freeMemory]
    [Registering JNI native method sun.misc.Unsafe.objectFieldOffset]
    [Registering JNI native method sun.misc.Unsafe.staticFieldOffset]
    [Registering JNI native method sun.misc.Unsafe.staticFieldBase]
    [Registering JNI native method sun.misc.Unsafe.ensureClassInitialized]
    [Dynamic-linking native method java.lang.ClassLoader.defineClass1 ... JNI]
    [Dynamic-linking native method java.io.FileInputStream.open ... JNI]
    [Dynamic-linking native method java.io.UnixFileSystem.getLength ... JNI]
    [Dynamic-linking native method java.io.FileInputStream.readBytes ... JNI]
    [Dynamic-linking native method java.io.FileInputStream.close0 ... JNI]
    [Dynamic-linking native method sun.reflect.NativeMethodAccessorImpl.invoke0 ... JNI]
    [Dynamic-linking native method java.net.PlainSocketImpl.initProto ... JNI]
    [Dynamic-linking native method java.io.FileOutputStream.writeBytes ... JNI]
    BigInteger is 553
    [Dynamic-linking native method java.net.InetAddress.init ... JNI]
    

Another JVM option which we'll use is -XX:+PrintGCDetails. Thanks to this, each GC summary output will contain more details.

Please note that with previous option we'll use -XX:+PrintGCTimeStamps. It enables GC logging with temstamp format. Remember also that by default the GC logging is printed directly to the console. But you can change this by using the -Xloggc:/home/bartosz/gc_logs.log option.

Analyze output of -verbose:gc

After discovering GC verbosity options, we can start to implement and analyze them. To analyze, we'll use simple class which generates some collections and tries to invoke directly GC through System.gc(). After each call of this method we should see an output with all garbage collected objects. This is our test class:

public class ClassGcVerbose {

  public static void main(String[] args) {
    makeSomeActions();
    invokeGc();

    makeSomeActions();
    makeSomeActions();
    makeSomeActions();
    makeSomeActions();
    makeSomeActions();
    File file = new File("/home/bartosz/tmp/testFile.txt");
    invokeGc();
  }

  private static void makeSomeActions() {
    String textC = "C";
    List<String> myTexts = new ArrayList<>();
    myTexts.add("A");
    myTexts.add("B");
    myTexts.add(textC);
  }

  private static void invokeGc() {
    // you should avoid to force GC manually; JVM knows better than you when to clean the memory. This entry is here only for learning purposes.
    System.out.println("------------------- Calling System.gc() -------------------- ");
    System.gc();
    System.out.println("------------------- After System.gc() call -------------------- ");
  }
}

After that, we need to run it with given JVM options (in Java 7 environment): -verbose:gc -XX:+PrintGCDetails -XX:+PrintGCTimeStamps. Now we can start to analyze the output:

------------------- Calling System.gc() -------------------- 
0,321: [GC [PSYoungGen: 1290K->448K(37376K)] 1290K->448K(121856K), 0,0364400 secs] [Times: user=0,00 sys=0,00, real=0,04 secs] 
0,358: [Full GC [PSYoungGen: 448K->0K(37376K)] [ParOldGen: 0K->315K(84480K)] 448K->315K(121856K) [PSPermGen: 3099K->3098K(21504K)], 0,0208850 secs] [Times: user=0,02 sys=0,00, real=0,02 secs] 
------------------- After System.gc() call -------------------- 
------------------- Calling System.gc() -------------------- 
0,379: [GC [PSYoungGen: 645K->32K(37376K)] 960K->347K(121856K), 0,0003770 secs] [Times: user=0,00 sys=0,00, real=0,00 secs] 
0,379: [Full GC [PSYoungGen: 32K->0K(37376K)] [ParOldGen: 315K->315K(84480K)] 347K->315K(121856K) [PSPermGen: 3099K->3099K(21504K)], 0,0058530 secs] [Times: user=0,01 sys=0,00, real=0,01 secs] 
------------------- After System.gc() call -------------------- 
Heap
 PSYoungGen      total 37376K, used 1935K [0x00000007d6880000, 0x00000007d9200000, 0x0000000800000000)
  eden space 32256K, 6% used [0x00000007d6880000,0x00000007d6a63f10,0x00000007d8800000)
  from space 5120K, 0% used [0x00000007d8d00000,0x00000007d8d00000,0x00000007d9200000)
  to   space 5120K, 0% used [0x00000007d8800000,0x00000007d8800000,0x00000007d8d00000)
 ParOldGen       total 84480K, used 315K [0x0000000783a00000, 0x0000000788c80000, 0x00000007d6880000)
  object space 84480K, 0% used [0x0000000783a00000,0x0000000783a4ede0,0x0000000788c80000)
 PSPermGen       total 21504K, used 3108K [0x0000000779400000, 0x000000077a900000, 0x0000000783a00000)
  object space 21504K, 14% used [0x0000000779400000,0x00000007797092d0,0x000000077a900000)

The output contains a lot of information. To understand it better, it must be decomposed to two separate parts:

  1. ------------------- Calling System.gc() -------------------- 
    0,321: [GC [PSYoungGen: 1290K->448K(37376K)] 1290K->448K(121856K), 0,0364400 secs] [Times: user=0,00 sys=0,00, real=0,04 secs] 
    0,358: [Full GC [PSYoungGen: 448K->0K(37376K)] [ParOldGen: 0K->315K(84480K)] 448K->315K(121856K) [PSPermGen: 3099K->3098K(21504K)], 0,0208850 secs] [Times: user=0,02 sys=0,00, real=0,02 secs] 
    ------------------- After System.gc() call -------------------- 
    ------------------- Calling System.gc() -------------------- 
    0,379: [GC [PSYoungGen: 645K->32K(37376K)] 960K->347K(121856K), 0,0003770 secs] [Times: user=0,00 sys=0,00, real=0,00 secs] 
    0,379: [Full GC [PSYoungGen: 32K->0K(37376K)] [ParOldGen: 315K->315K(84480K)] 347K->315K(121856K) [PSPermGen: 3099K->3099K(21504K)], 0,0058530 secs] [Times: user=0,01 sys=0,00, real=0,01 secs] 
    ------------------- After System.gc() call -------------------- 
    

    As you can see, there are some areas with JVM generations. You can see there young (PSYoungGen), permanent (PSPermGen) and old gen (ParOldGen) spaces. This part can be different for each Java versions. This output was made for Java 7.

    Every entry contains some values inside [] part, as for example: 1290K->448K(37376K). In this case, the first value (1290K) means the space taken before GC job. The second value means the space taken after the GC job (448K). The last value (37376K) signifies total available space. If we take the PSYoungGen case from the first line, we can tell that before GC job, young generation taken 1290kb and after only 448kb. The whole space available for this generation is 37376kb.

    The value preceding GC summary (0,321, 0,379...) informs us when GC was launched. This number means the number of miliseconds after JVM started. In our case, GC job was launched twice 3 miliseconds after this event. You can receive even more acceptable proof by adding some Thread.sleep(3000) between two System.gc() invocations. Now, our test method will look like:

    public static void main(String[] args) {
      makeSomeActions();
      invokeGc();
    
      try {
        Thread.sleep(3000);
      } catch (InterruptedException e) {
        e.printStackTrace();
      }
      makeSomeActions();
      makeSomeActions();
      makeSomeActions();
      makeSomeActions();
      makeSomeActions();
      File file = new File("/home/bartosz/tmp/testFile.txt");
      invokeGc();
    }
    

    After this change, the output should show something like that:

    ------------------- Calling System.gc() -------------------- 
    0,234: [GC [PSYoungGen: 1290K->368K(37376K)] 1290K->368K(121856K), 0,0121270 secs] [Times: user=0,00 sys=0,00, real=0,02 secs] 
    0,246: [Full GC [PSYoungGen: 368K->0K(37376K)] [ParOldGen: 0K->304K(84480K)] 368K->304K(121856K) [PSPermGen: 2951K->2950K(21504K)], 0,0267940 secs] [Times: user=0,03 sys=0,01, real=0,02 secs] 
    ------------------- After System.gc() call -------------------- 
    ------------------- Calling System.gc() -------------------- 
    3,273: [GC [PSYoungGen: 2580K->128K(37376K)] 2885K->432K(121856K), 0,0051080 secs] [Times: user=0,00 sys=0,01, real=0,01 secs] 
    3,278: [Full GC [PSYoungGen: 128K->0K(37376K)] [ParOldGen: 304K->303K(84480K)] 432K->303K(121856K) [PSPermGen: 3101K->3101K(21504K)], 0,0094500 secs] [Times: user=0,01 sys=0,01, real=0,01 secs] 
    ------------------- After System.gc() call --------------------
    

    The last interesting information is contained at the end of [] parenthesis. It means the time took by GC to make its job. In our case, it's "0,0121270 secs" or "0,0051080 secs".

    [Times : ...] statistics represents the Real,User and Sys process time statistics.

  2. Heap
     PSYoungGen      total 37376K, used 1935K [0x00000007d6880000, 0x00000007d9200000, 0x0000000800000000)
      eden space 32256K, 6% used [0x00000007d6880000,0x00000007d6a63f10,0x00000007d8800000)
      from space 5120K, 0% used [0x00000007d8d00000,0x00000007d8d00000,0x00000007d9200000)
      to   space 5120K, 0% used [0x00000007d8800000,0x00000007d8800000,0x00000007d8d00000)
     ParOldGen       total 84480K, used 315K [0x0000000783a00000, 0x0000000788c80000, 0x00000007d6880000)
      object space 84480K, 0% used [0x0000000783a00000,0x0000000783a4ede0,0x0000000788c80000)
     PSPermGen       total 21504K, used 3108K [0x0000000779400000, 0x000000077a900000, 0x0000000783a00000)
      object space 21504K, 14% used [0x0000000779400000,0x00000007797092d0,0x000000077a900000)
    

    This output is guaranteed by -XX:+PrintGCDetails -XX:+PrintGCTimeStamps arguments. As you can see, it represents every area in the heap. It's more detailed than the output saw in the previous point because it details the memory use of sub-generations (eden).

    In our case we can see that the objects in eden space took only 6% of available space while old generation was never used. Unlike permanent generation which was occupied in 14%.

    This type of information can be useful to tune the application because it shows the heap state when the application shutdowns.

This article shows us how to manipulate verbose argument to see exactly the job made by Garbage Collector. We can see that this argument accepts different values (jni, class), but only the one can display the information about GC (gc). Coupled with another arguments of the same type (-XX:+PrintGCDetails), it provides some statistics about memory heap lifecycle, as space taken before and after GC, time spent to make the GC job.

Share on: