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

JVM Tutorials - Herong's Tutorial Examples

∟"-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:

herong> java -XX:+PrintGC -XX:+UseSerialGC -Xms1m -Xmx2m \
   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:

GC was performed regularly at an equal interval of 1567 runs of the test method. This is expected, because there is no other threads running except for the loop of repeating runs of the test method.
All 6 GCs were performed outside the test loop and had no impact on the execution time of the test.
4 runs were interrupted by something other than GC. I don't know what caused those 4 interruptions, may be come some scheduled events on my Windows system?