Disclaimer
I am in no way well versed on the Garbage-First Garbage Collector and this
question inspired me to check it out for the first time. There is a chance
I may be wrong with some of my information.
Intro
To get more information about the Garbage-First Garbage Collector (G1GC), the
Garbage-First Garbage Collection paper (here,
here, here and here) is an
invaluable resource. You can find an introduction to the G1GC
here. The HotSpot Glossary comes in handy to
understand JVM terms. The following papers were also helpful in further
understanding Garbage Collection:
- A Hard Look at Hard Real-Time Garbage Collection: here and here
- Non-Blocking Garbage Collection for Multiprocessors: here and here
- Non-blocking Root Scanning for Real-Time Garbage Collection: here
- Non-blocking Object Copy for Real-Time Garbage Collection: here and here
With these resources and an OpenJDK 7 debug build,
you can start to understand the G1GC log.
Definitions
Using the papers and web pages referenced above, here are some useful
definitions of terms that came up most often:
- concurrent marking: Both provides collection ”completeness” and
identifies regions ripe for reclamation via compacting evacuation. Provides
collector completeness without imposing any order on region choice for
collection sets. Provides the live data information that allows regions to be
collected in “garbage-first” order.
- heap: The area of memory used by the JVM for dynamic memory allocation.
- heap region: The heap is partitioned into a set of equal-sized heap
regions. The Garbage-First heap is divided into equal-sized heap regions, each
a contiguous range of virtual memory.
- marking bitmap: Contains one bit for each address that can be the start of
an object.
- remembered set: A data structure that indicates heap locations outside the
region that may contain pointers to objects in the region. Each region has an
associated remembered set, which indicates all locations that might contain
pointers to (live) objects within the region. Garbage-First remembered sets
record pointers from all regions (with some exceptions). A current buffer or
sequence of modified cards. A data structure that records pointers between
generations.
- root set: A set of objects which is known to be directly accessible. The
locations from which all live objects are reachable.
Source Code
To understand the G1GC log better, I used the following OpenJDK 7
source files:
- hotspot/src/share/vm/gc_implementation/g1/concurrentMarkThread.cpp
- hotspot/src/share/vm/gc_implementation/g1/concurrentMark.cpp
- hotspot/src/share/vm/gc_implementation/g1/concurrentMark.hpp
- hotspot/src/share/vm/gc_implementation/g1/g1_specialized_oop_closures.hpp
- hotspot/src/share/vm/gc_implementation/g1/g1CollectedHeap.cpp
- hotspot/src/share/vm/gc_implementation/g1/g1CollectedHeap.hpp
- hotspot/src/share/vm/gc_implementation/g1/g1CollectorPolicy.cpp
- hotspot/src/share/vm/gc_implementation/g1/g1CollectorPolicy.hpp
- hotspot/src/share/vm/gc_implementation/g1/g1OopClosures.hpp
- hotspot/src/share/vm/gc_implementation/g1/g1OopClosures.inline.hpp
- hotspot/src/share/vm/gc_implementation/g1/g1RemSet.cpp
- hotspot/src/share/vm/memory/sharedHeap.cpp
- hotspot/src/share/vm/memory/sharedHeap.hpp
- hotspot/src/share/vm/utilities/taskqueue.hpp
- hotspot/src/share/vm/runtime/timer.cpp
- hotspot/src/share/vm/runtime/timer.hpp
- hotspot/src/share/vm/gc_implementation/g1/vm_operations_g1.cpp
- hotspot/src/share/vm/gc_implementation/g1/vm_operations_g1.hpp
Log Analysis
Below is an annotated copy of the G1GC log in question.
44900.297: [GC pause (young) (initial-mark), 0.08894851 secs]
^^^^^^^^^^^ Elapsed seconds from JVM start
^^^^^^^^^ Collection pause at safe-point
^^^^^^^^ In full young GC mode
^^^^^^^^^^^^^^^ Last pause included initial mark
^^^^^^^^^^^^^^^^^^ Elapsed seconds in method
44900.386: [GC concurrent-mark-start]
^^^^^^^^^^^ Elapsed seconds from JVM start
^^^^^^^^^^^^^^^^^^^^^^^^^^ Concurrent mark thread started
[Parallel Time: 83.7 ms]
^^^^^^^^^^^^^^^^^^^^^^^^^^^^ Elapsed milliseconds for all GC worker threads to finish
[GC Worker Start Time (ms): 44900297.6 44900297.6 44900297.6 44900297.6 44900297.6 44900297.7 44900297.7 44900297.7 44900297.7 44900297.7 44900297.7 44900297.7 44900297.7
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^... Elapsed seconds from JVM start that GC worker threads were started
Avg: 44900297.7, Min: 44900297.6, Max: 44900297.7, Diff: 0.1]
^^^^^^^^^^^^^^^^^^^^^^ Average GC worker thread start time (elapsed seconds from JVM start)
^^^^^^^^^^^^^^^^^ Minimum GC worker thread start time (elapsed seconds from JVM start)
^^^^^^^^^^^^^^^^^ Maximum GC worker thread start time (elapsed seconds from JVM start)
^^^^^^^^^^^^^^ Total seconds to start all GC worker threads
[Update RS (ms): 23.5 24.3 25.0 25.0 23.9 24.4 25.2 24.1 25.7 24.7 24.8 24.4 24.7
^^^^^^^^^^^^^^^^^^^^^^^^... Elapsed milliseconds for each GC worker thread to update cards in remembered sets during an evacuation pause
Avg: 24.6, Min: 23.5, Max: 25.7, Diff: 2.1]
^^^^^^^^^^^^^^^^^ Average GC worker thread milliseconds to update RS
^^^^^^^^^^^^ Minimum GC worker thread milliseconds to update RS
^^^^^^^^^^^^ Maximum GC worker thread milliseconds to update RS
^^^^^^^^^^^^^^ Minimum/maximum delta of GC worker thread milliseconds to update RS
[Processed Buffers : 16 19 19 23 20 24 18 18 18 17 20 16 19
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^... Total remembered set buffers processed by each GC worker thread
Sum: 247, Avg: 19, Min: 16, Max: 24, Diff: 8]
^^^^^^^^^^... Summary information for total remembered set buffers processed by all GC worker thread
[Ext Root Scanning (ms): 2.2 2.7 2.2 2.6 3.0 3.1 2.2 1.1 2.3 3.0 2.2 2.4 2.9
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^... Elapsed milliseconds for each GC worker thread to process heap roots during an evacuation pause
Avg: 2.4, Min: 1.1, Max: 3.1, Diff: 2.0]
^^^^^^^... Summary information for total elapsed milliseconds for all GC worker thread to process heap roots during an evacuation pause
[Mark Stack Scanning (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^... Elapsed milliseconds for each GC worker thread to scan strong roots in the mark stack during an evacuation pause
Avg: 0.0, Min: 0.0, Max: 0.0, Diff: 0.0]
^^^^^^^... Summary information for total milliseconds for all GC worker thread to scan strong roots in the mark stack during an evacuation pause
[Scan RS (ms): 14.1 14.6 14.5 14.3 14.6 14.2 14.4 14.5 14.0 13.9 14.6 14.5 14.0
^^^^^^^^^^^^^^^^^^^^^^... Elapsed milliseconds for each GC worker thread to scan for dirty cards in a heap region to update the remembered set
Avg: 14.3, Min: 13.9, Max: 14.6, Diff: 0.8]
^^^^^^^^^^^^^... Summary information for total elapsed milliseconds for all GC worker thread to scan for dirty cards in a heap region to update the remembered set
[Object Copy (ms): 41.4 39.5 39.4 39.0 39.6 39.5 39.1 41.4 39.0 39.3 39.3 39.8 39.5
^^^^^^^^^^^^^^^^^^^^^^^^^^... Elapsed milliseconds for each GC worker thread to scan root sets for pointers to include in this heap region's remembered set during an evacuation pause
Avg: 39.7, Min: 39.0, Max: 41.4, Diff: 2.4]
^^^^^^^^^^^^^... Summary information for total elapsed milliseconds for all GC worker thread to scan root sets for pointers to include in this heap region's remembered set during an evacuation pause
[Termination (ms): 1.3 1.4 1.5 1.6 1.5 1.4 1.6 1.4 1.5 1.7 1.5 1.4 1.3
^^^^^^^^^^^^^^^^^^^^^^^^^^... Elapsed milliseconds for each GC worker thread to terminate scanning root sets for pointers to include in this heap region's remembered set during an evacuation pause
Avg: 1.5, Min: 1.3, Max: 1.7, Diff: 0.4]
^^^^^^^^^^^^^^... Summary information for total elapsed milliseconds for all GC worker thread to terminate scanning root sets for pointers to include in this heap region's remembered set during an evacuation pause
[Termination Attempts : 1185 1205 1219 1436 1171 1231 1471 1237 1461 1526 1353 1259 1170
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^... Total attempts for each GC worker thread to terminate scanning root sets for pointers to include in this heap region's remembered set during an evacuation pause
Sum: 16924, Avg: 1301, Min: 1170, Max: 1526, Diff: 356]
^^^^^^^^^^^^^^^... Summary information for total attempts for all GC worker thread to terminate scanning root sets for pointers to include in this heap region's remembered se
