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:

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.


If you liked it, you should read:

📚 Newsletter Get new posts, recommended reading and other exclusive information every week. SPAM free - no 3rd party ads, only the information about waitingforcode!