"-XX:+PrintGC" - Watching GC (Garbage Collection) Logs

This section provides a tutorial example on how to use the HotSpot JVM command option, -XX:+PrintGC, to watch GC (Garbage Collection) logs. JVM performs GC with a regular interval during the test run loop and has no impact on the execution time of the test code.

In order to find out the impact on the execution time by the GC (Garbage Collection), I did another test with the "-XX:+PrintGC" HotSpot JVM option:

C:\herong\jvm>java -XX:+PrintGC BenchmarkRunner
   BenchmarkLoopTest emptyLoop 1000000 3 3
Are you ready?
y

Waking up the JIT compiler...
Run: 1, Time: 6426, Test returns: 3
Run: 2, Time: 3352, Test returns: 3
Run: 3, Time: 3352, Test returns: 3
...
Run: 1222, Time: 2514, Test returns: 3
[GC 896K->114K(5056K), 0.0023509 secs] // GC #1
Run: 1223, Time: 2515, Test returns: 3
...
Run: 2790, Time: 1955, Test returns: 3
[GC 1010K->114K(5056K), 0.0005031 secs] // GC #2, 1568 runs after #1
Run: 2791, Time: 1956, Test returns: 3
...
Run: 4356, Time: 1956, Test returns: 3
[GC 1010K->114K(5056K), 0.0002065 secs] // GC #3, 1566 runs after #2
Run: 4357, Time: 1956, Test returns: 3
...
Run: 5090, Time: 1956, Test returns: 3
Run: 5091, Time: 11454, Test returns: 3 // Interruption #1
Run: 5092, Time: 1956, Test returns: 3
...
Run: 5240, Time: 1956, Test returns: 3
Run: 5241, Time: 21791, Test returns: 3 // Interruption #2
Run: 5242, Time: 1955, Test returns: 3
...
Run: 5921, Time: 1955, Test returns: 3
[GC 1010K->114K(5056K), 0.0001665 secs] // GC #4, 1565 runs after #3
Run: 5922, Time: 1956, Test returns: 3

Run: 6413, Time: 1955, Test returns: 3
Run: 6414, Time: 11454, Test returns: 3 // Interruption #3
Run: 6415, Time: 1956, Test returns: 3

Run: 7398, Time: 1955, Test returns: 3
Run: 7399, Time: 12013, Test returns: 3 // Interruption #4
Run: 7400, Time: 2515, Test returns: 3
...
Run: 7488, Time: 1956, Test returns: 3
[GC 1010K->114K(5056K), 0.0000810 secs] // GC #5, 1567 runs after #4
Run: 7489, Time: 1956, Test returns: 3
...
Run: 9057, Time: 1956, Test returns: 3
[GC 1010K->114K(5056K), 0.0000788 secs] // GC #6, 1569 runs after #5
Run: 9058, Time: 1956, Test returns: 3
...

The test result tells me that:

Last update: 2010.

Table of Contents

 About This Book

 Downloading and Installing JDK 1.8.0 on Windows

 Downloading and Installing JDK 1.7.0 on Windows

 java.lang.Runtime Class - The JVM Instance

 java.lang.System Class - The Operating System

 ClassLoader Class - Class Loaders

 Class Class - Class Reflections

 Sun's JVM - Java HotSpot VM

 JRockit JVM 28.2.7 by Oracle Corporation

 JVM Runtime Data Areas

 Memory Management and Garbage Collectors

 Garbage Collection Tests

 JVM Stack, Frame and Stack Overflow

 Thread Testing Program and Result

 CPU Impact of Multi-Thread Applications

 I/O Impact of Multi-Thread Applications

 CDS (Class Data Sharing)

Micro Benchmark Runner and JVM Options

 What Is Micro Benchmark?

 BenchmarkRunner.java - Benchmark Runner Program

 emptyLoop() - The Empty Loop Test Method

 "-XX:+PrintCompilation" - Watching JIT Compilation Logs

"-XX:+PrintGC" - Watching GC (Garbage Collection) Logs

 "-Xms" and "-Xmx" - Avoiding GC with Large Memory Size

 Benchmark Affected by Other Running Applications

 "-Xint" - Running in Interpreted-Only Mode

 Micro Benchmark Tests on "int" Operations

 Micro Benchmark Tests on "long" Operations

 Micro Benchmark Tests in JIT Compilation Mode

 Micro Benchmark Tests on "float" and "double" Operations

 Outdated Tutorials

 References

 PDF Printing Version