RFR: 8242078: G1: Improve concurrent refinement analytics and logging

Kim Barrett kim.barrett at oracle.com
Sat Apr 4 21:21:01 UTC 2020


Please review this change to improve the data collection and logging for
concurrent refinement.

Both concurrent refinement threads and refining mutator threads now use a
common structure for collecting stats about refinement.  This simplifies
and improves the reporting and analytics based on that information.

Changed logging to be in the pause-start recording stage, under the control
of the (gc, refine, stats) tagset.  Concurrent refinement statistics are no
longer part of the RemsetSummary.

In the gathering and reporting, made a nomenclature change from "logged"
cards to "dirtied" cards.  This was originally done in support of some
experiments with deferred dirtying of logged cards, but I think it makes
sense even in the absence of such deferral.

As part of this change, moved the call to G1DirtyCardQueue::concatenate_logs
earlier, so that other code (including the concurrent refinement stats
recording code) doesn't need to deal with the pre-flushed state.  Also
report time spent specifically in this phase.

Because this change uses phase time's cur_collection_start_sec() (when
computing the rate of dirty card generation) it "suffers" from the same
questions around GC pause start time as discussed in JDK-8240779.

CR:
https://bugs.openjdk.java.net/browse/JDK-8242078

Webrev:
https://cr.openjdk.java.net/~kbarrett/8242078/open.00/

Testing:
mach5 tier1-5

Locally (linux-x64) ran some tests and verified the log messages looked as
expected; for example:
GC(741) Mutator refinement: 0.00ms, refined: 0, precleaned: 0, dirtied: 107106
GC(741) Concurrent refinement: 1299.56ms, refined: 92394, precleaned: 4196, dirtied: 0
GC(741) Total refinement: 1299.56ms, refined: 92394, precleaned: 4196, dirtied: 107106
GC(741) Concurrent refinement rate: 71.10 cards/ms
GC(741) Generate dirty cards rate: 163.32 cards/ms




More information about the hotspot-gc-dev mailing list