Java Reference
In-Depth Information
50.541: [GC pause (young) (initial-mark), 0.27767100 secs]
[Eden: 1220M(1220M)->0B(1220M)
Survivors: 144M->144M Heap: 3242M(4096M)->2093M(4096M)]
[Times: user=1.02 sys=0.04, real=0.28 secs]
As in a regular young collection, the application threads were stopped (for 0.28 seconds), and
the young generation was emptied (71 MB of data was moved from the young generation to
the old generation). The initial-mark output announces that the background concurrent cycle
has begun. Since the initial mark phase also requires all application threads to be stopped, G1
takes advantage of the young GC cycle to do that work. The impact of adding the initial
mark phase to the young GC wasn't that large: it used 20% more CPU cycles than the previ-
ous collection, even though the pause was only slightly longer. (Fortunately, there were spare
CPU cycles on the machine for the parallel G1 threads, or the pause would have been
Next, G1 scans the root region:
50.819: [GC concurrent-root-region-scan-start]
51.408: [GC concurrent-root-region-scan-end, 0.5890230]
This takes 0.58 seconds, but it doesn't stop the application threads; it only uses the back-
ground threads. However, this phase cannot be interrupted by a young collection, so having
available CPU cycles for those background threads is crucial. If the young generation hap-
pens to fill up during the root region scanning, the young collection (which has stopped all
the application threads) must wait for the root scanning to complete. In effect, this means a
longer-than-usual pause to collect the young generation. That situation is shown in the GC
log like this:
350.994: [GC pause (young)
351.093: [GC concurrent-root-region-scan-end, 0.6100090]
351.093: [GC concurrent-mark-start],
0.37559600 secs]
The GC pause here starts before the end of the root region scanning, which (along with the
interleaved output) indicates that it was waiting. The timestamps show that application
threads waited about 100 ms—which is why the duration of the young GC pause is about
100 ms longer than the average duration of other pauses in this log. (If this occurs frequently,
it is an indication that G1 needs to be better tuned, as discussed in the next section.)
Search WWH ::

Custom Search