RFR: JDK-8297796 GenShen: instrument the remembered set scan [v14]
Y. Srinivas Ramakrishna
ysr at openjdk.org
Thu Dec 22 04:16:41 UTC 2022
> **Updated 12/21**
>
> **Summary:**
> The main change is card stats collection during remembered set (RS) and update refs (UR) phases when the card-table is scanned. The code is protected by a new non-product only flag `ShenandoahEnableCardStats`, which is on by default in debug builds and off in the optimized build.
>
> We tested the impact of the code with the flag enabled in product mode and felt the impact was non-trivial. We might, in the future, enable the code in product mode if performance can be improved.
>
> Stats are logged per worker thread at the end of each RS and UR scan. These stats are specific to the most recent round of scanning. Global cumulative stats across all threads (but specific to RS or UR) are also maintained, and these are logged at periodic intervals as determined by the setting of `ShenandoahCardStatsLogInterval`.
>
> **Format of stats produced and how to interpret them: (sample)**
>
> The following format is an example from a slowdebug run where the logging is enabled. In this case there are 2 concurrent gc worker threads, and `ShenandoahCardStatsLogInterval` was set at 2. The first two logs show the stats for those particular scans for each of the two worker threads, and the next set show the stats for particular scans for the two worker threads, followed by a cumulative one for that type of scan (RS or UR) across all workers and scans of that type, respectively.
>
>
> [560.766s][info][gc,remset ] GC(13) Scan Remembered Set
> [560.766s][info][gc,remset ] GC(13) Worker 0 Card Stats Histo:
> [560.766s][info][gc,remset ] GC(13) dirty_run: [ 0.00 0.00 0.00 99.61 100.00 ]
> [560.766s][info][gc,remset ] GC(13) clean_run: [ 0.00 0.00 0.00 0.00 53.12 ]
> [560.766s][info][gc,remset ] GC(13) dirty_cards: [ 0.00 99.61 99.61 99.61 100.00 ]
> [560.766s][info][gc,remset ] GC(13) clean_cards: [ 0.00 0.00 0.00 0.00 53.12 ]
> [560.766s][info][gc,remset ] GC(13) max_dirty_run: [ 0.00 99.61 99.61 99.61 100.00 ]
> [560.766s][info][gc,remset ] GC(13) max_clean_run: [ 0.00 0.00 0.00 0.00 53.12 ]
> [560.766s][info][gc,remset ] GC(13) dirty_objs: [ 0.00 0.00 0.00 818.36 1366.00 ]
> [560.766s][info][gc,remset ] GC(13) clean_objs: [ 0.00 0.00 0.00 0.00 8.00 ]
> [560.766s][info][gc,remset ] GC(13) dirty_scans: [ 0.00 0.00 0.00 705.08 1365.00 ]
> [560.766s][info][gc,remset ] GC(13) clean_scans: [ 0.00 0.00 0.00 0.00 0.00 ]
> [560.766s][info][gc,remset ] GC(13) alternations: [ 0.00 0.00 0.00 0.00 16.00 ]
> [560.766s][info][gc,remset ] GC(13) Worker 1 Card Stats Histo:
> [560.766s][info][gc,remset ] GC(13) dirty_run: [ 0.00 0.00 0.00 96.88 100.00 ]
> [560.766s][info][gc,remset ] GC(13) clean_run: [ 0.00 0.00 0.00 0.00 46.88 ]
> [560.766s][info][gc,remset ] GC(13) dirty_cards: [ 18.75 82.81 98.44 99.61 100.00 ]
> [560.766s][info][gc,remset ] GC(13) clean_cards: [ 0.00 0.00 0.00 0.00 46.88 ]
> [560.766s][info][gc,remset ] GC(13) max_dirty_run: [ 18.75 82.81 98.44 99.61 100.00 ]
> [560.766s][info][gc,remset ] GC(13) max_clean_run: [ 0.00 0.00 0.00 0.00 46.88 ]
> [560.766s][info][gc,remset ] GC(13) dirty_objs: [ 0.00 269.53 353.52 814.45 1366.00 ]
> [560.766s][info][gc,remset ] GC(13) clean_objs: [ 0.00 0.00 0.00 0.00 3.00 ]
> [560.766s][info][gc,remset ] GC(13) dirty_scans: [ 0.00 263.67 351.56 671.88 1365.00 ]
> [560.766s][info][gc,remset ] GC(13) clean_scans: [ 0.00 0.00 0.00 0.00 0.00 ]
> [560.766s][info][gc,remset ] GC(13) alternations: [ 0.00 0.00 0.00 0.00 3.00 ]
> [560.766s][info][gc ] GC(13) Concurrent remembered set scanning 1150.359ms
> [560.766s][info][gc,start ] GC(13) Concurrent marking roots
> ...
> [585.433s][info][gc ] GC(13) Concurrent evacuation 6225.829ms
> [585.433s][info][gc,start ] GC(13) Pause Init Update Refs
> [585.434s][info][gc ] GC(13) Pause Init Update Refs 0.264ms
> [585.434s][info][gc,start ] GC(13) Concurrent update references
> [585.434s][info][gc,task ] GC(13) Using 2 of 4 workers for concurrent reference update
> [585.567s][info][gc ] Average MMU = 2.925
> [590.583s][info][gc ] Average MMU = 1.509
> [595.600s][info][gc ] Average MMU = 0.835
> [600.618s][info][gc ] Average MMU = 0.447
> [605.635s][info][gc ] Average MMU = 0.253
> [610.651s][info][gc ] Average MMU = 0.114
> [615.669s][info][gc ] Average MMU = 0.130
> [620.686s][info][gc ] Average MMU = 0.129
> [622.209s][info][gc,remset ] GC(13) Update Refs
> [622.209s][info][gc,remset ] GC(13) Worker 0 Card Stats Histo:
> [622.209s][info][gc,remset ] GC(13) dirty_run: [ 0.00 0.00 0.00 3.12 100.00 ]
> [622.209s][info][gc,remset ] GC(13) clean_run: [ 0.00 0.00 0.00 3.12 100.00 ]
> [622.209s][info][gc,remset ] GC(13) dirty_cards: [ 0.00 3.12 50.00 99.61 100.00 ]
> [622.209s][info][gc,remset ] GC(13) clean_cards: [ 0.00 0.00 26.56 92.19 100.00 ]
> [622.209s][info][gc,remset ] GC(13) max_dirty_run: [ 0.00 1.56 29.69 99.61 100.00 ]
> [622.209s][info][gc,remset ] GC(13) max_clean_run: [ 0.00 0.00 9.38 70.31 100.00 ]
> [622.209s][info][gc,remset ] GC(13) dirty_objs: [ 0.00 0.00 0.00 50.00 1366.00 ]
> [622.209s][info][gc,remset ] GC(13) clean_objs: [ 0.00 0.00 3.98 54.88 64.00 ]
> [622.209s][info][gc,remset ] GC(13) dirty_scans: [ 0.00 0.00 0.00 33.98 1365.00 ]
> [622.209s][info][gc,remset ] GC(13) clean_scans: [ 0.00 0.00 0.00 1.00 16.00 ]
> [622.209s][info][gc,remset ] GC(13) alternations: [ 0.00 0.00 0.00 2.99 33.00 ]
> [622.209s][info][gc,remset ] GC(13) Worker 1 Card Stats Histo:
> [622.209s][info][gc,remset ] GC(13) dirty_run: [ 0.00 0.00 0.00 0.00 0.00 ]
> [622.209s][info][gc,remset ] GC(13) clean_run: [ 0.00 0.00 0.00 0.00 0.00 ]
> [622.210s][info][gc,remset ] GC(13) dirty_cards: [ 0.00 0.00 0.00 0.00 0.00 ]
> [622.210s][info][gc,remset ] GC(13) clean_cards: [ 0.00 0.00 0.00 0.00 0.00 ]
> [622.210s][info][gc,remset ] GC(13) max_dirty_run: [ 0.00 0.00 0.00 0.00 0.00 ]
> [622.210s][info][gc,remset ] GC(13) max_clean_run: [ 0.00 0.00 0.00 0.00 0.00 ]
> [622.210s][info][gc,remset ] GC(13) dirty_objs: [ 0.00 0.00 0.00 0.00 0.00 ]
> [622.210s][info][gc,remset ] GC(13) clean_objs: [ 0.00 0.00 0.00 0.00 0.00 ]
> [622.210s][info][gc,remset ] GC(13) dirty_scans: [ 0.00 0.00 0.00 0.00 0.00 ]
> [622.210s][info][gc,remset ] GC(13) clean_scans: [ 0.00 0.00 0.00 0.00 0.00 ]
> [622.210s][info][gc,remset ] GC(13) alternations: [ 0.00 0.00 0.00 0.00 0.00 ]
> [622.210s][info][gc ] GC(13) Concurrent update references 36776.258ms
> ...
> (init[627.626s][info][gc,remset ] GC(15) Scan Remembered Set
> [627.626s][info][gc,remset ] GC(15) Worker 0 Card Stats Histo:
> [627.626s][info][gc,remset ] GC(15) dirty_run: [ 0.00 0.00 0.00 1.56 100.00 ]
> [627.626s][info][gc,remset ] GC(15) clean_run: [ 0.00 0.00 0.00 4.69 100.00 ]
> [627.626s][info][gc,remset ] GC(15) dirty_cards: [ 0.00 0.00 6.25 32.81 100.00 ]
> [627.626s][info][gc,remset ] GC(15) clean_cards: [ 0.00 48.44 90.62 98.44 100.00 ]
> [627.626s][info][gc,remset ] GC(15) max_dirty_run: [ 0.00 0.00 3.12 15.62 100.00 ]
> [627.626s][info][gc,remset ] GC(15) max_clean_run: [ 0.00 23.44 60.94 95.31 100.00 ]
> [627.626s][info][gc,remset ] GC(15) dirty_objs: [ 0.00 0.00 45.90 164.06 1366.00 ]
> [627.626s][info][gc,remset ] GC(15) clean_objs: [ 0.00 11.91 53.91 60.94 63.00 ]
> [627.626s][info][gc,remset ] GC(15) dirty_scans: [ 0.00 0.00 31.84 150.39 1365.00 ]
> [627.626s][info][gc,remset ] GC(15) clean_scans: [ 0.00 0.00 1.00 1.99 11.00 ]
> [627.626s][info][gc,remset ] GC(15) alternations: [ 0.00 0.00 1.99 6.00 24.00 ]
> [627.627s][info][gc,remset ] GC(15) Worker 1 Card Stats Histo:
> [627.627s][info][gc,remset ] GC(15) dirty_run: [ 0.00 0.00 0.00 3.12 100.00 ]
> [627.627s][info][gc,remset ] GC(15) clean_run: [ 0.00 0.00 0.00 1.56 100.00 ]
> [627.627s][info][gc,remset ] GC(15) dirty_cards: [ 0.00 6.25 99.61 99.61 100.00 ]
> [627.627s][info][gc,remset ] GC(15) clean_cards: [ 0.00 0.00 0.00 70.31 100.00 ]
> [627.627s][info][gc,remset ] GC(15) max_dirty_run: [ 0.00 3.12 99.61 99.61 100.00 ]
> [627.627s][info][gc,remset ] GC(15) max_clean_run: [ 0.00 0.00 0.00 53.12 100.00 ]
> [627.627s][info][gc,remset ] GC(15) dirty_objs: [ 0.00 0.00 0.00 0.00 1365.00 ]
> [627.627s][info][gc,remset ] GC(15) clean_objs: [ 0.00 0.00 0.00 40.82 64.00 ]
> [627.627s][info][gc,remset ] GC(15) dirty_scans: [ 0.00 0.00 0.00 0.00 1364.00 ]
> [627.627s][info][gc,remset ] GC(15) clean_scans: [ 0.00 0.00 0.00 0.00 16.00 ]
> [627.627s][info][gc,remset ] GC(15) alternations: [ 0.00 0.00 0.00 0.00 33.00 ]
> [627.627s][info][gc,remset ] GC(15) Cumulative stats
> [627.627s][info][gc,remset ] GC(15) dirty_run: [ 0.00 0.00 0.00 6.25 100.00 ]
> [627.627s][info][gc,remset ] GC(15) clean_run: [ 0.00 0.00 0.00 1.56 100.00 ]
> [627.627s][info][gc,remset ] GC(15) dirty_cards: [ 0.00 40.62 99.61 99.61 100.00 ]
> [627.627s][info][gc,remset ] GC(15) clean_cards: [ 0.00 0.00 0.00 31.25 100.00 ]
> [627.627s][info][gc,remset ] GC(15) max_dirty_run: [ 0.00 23.44 99.61 99.61 100.00 ]
> [627.627s][info][gc,remset ] GC(15) max_clean_run: [ 0.00 0.00 0.00 12.50 100.00 ]
> [627.627s][info][gc,remset ] GC(15) dirty_objs: [ 0.00 0.00 0.00 326.17 1366.00 ]
> [627.627s][info][gc,remset ] GC(15) clean_objs: [ 0.00 0.00 0.00 3.98 64.00 ]
> [627.627s][info][gc,remset ] GC(15) dirty_scans: [ 0.00 0.00 0.00 314.45 1365.00 ]
> [627.627s][info][gc,remset ] GC(15) clean_scans: [ 0.00 0.00 0.00 0.00 16.00 ]
> [627.627s][info][gc,remset ] GC(15) alternations: [ 0.00 0.00 0.00 0.00 33.00 ]
> [627.627s][info][gc ] GC(15) Concurrent remembered set scanning 1119.698ms
> ...
> [631.875s][info][gc,remset ] GC(15) Update Refs
> [631.875s][info][gc,remset ] GC(15) Worker 0 Card Stats Histo:
> [631.875s][info][gc,remset ] GC(15) dirty_run: [ 0.00 0.00 0.00 3.12 100.00 ]
> [631.875s][info][gc,remset ] GC(15) clean_run: [ 0.00 0.00 0.00 3.12 100.00 ]
> [631.875s][info][gc,remset ] GC(15) dirty_cards: [ 0.00 4.69 99.61 99.61 100.00 ]
> [631.875s][info][gc,remset ] GC(15) clean_cards: [ 0.00 0.00 0.00 90.62 100.00 ]
> [631.875s][info][gc,remset ] GC(15) max_dirty_run: [ 0.00 3.12 99.61 99.61 100.00 ]
> [631.875s][info][gc,remset ] GC(15) max_clean_run: [ 0.00 0.00 0.00 68.75 100.00 ]
> [631.875s][info][gc,remset ] GC(15) dirty_objs: [ 0.00 0.00 0.00 29.88 1365.00 ]
> [631.875s][info][gc,remset ] GC(15) clean_objs: [ 0.00 0.00 0.00 52.93 64.00 ]
> [631.875s][info][gc,remset ] GC(15) dirty_scans: [ 0.00 0.00 0.00 22.85 1364.00 ]
> [631.875s][info][gc,remset ] GC(15) clean_scans: [ 0.00 0.00 0.00 0.00 11.00 ]
> [631.875s][info][gc,remset ] GC(15) alternations: [ 0.00 0.00 0.00 1.99 24.00 ]
> [631.875s][info][gc,remset ] GC(15) Worker 1 Card Stats Histo:
> [631.875s][info][gc,remset ] GC(15) dirty_run: [ 0.00 0.00 0.00 26.56 100.00 ]
> [631.875s][info][gc,remset ] GC(15) clean_run: [ 0.00 0.00 0.00 0.00 100.00 ]
> [631.875s][info][gc,remset ] GC(15) dirty_cards: [ 0.00 62.50 99.61 99.61 100.00 ]
> [631.875s][info][gc,remset ] GC(15) clean_cards: [ 0.00 0.00 0.00 0.00 100.00 ]
> [631.875s][info][gc,remset ] GC(15) max_dirty_run: [ 0.00 59.38 99.61 99.61 100.00 ]
> [631.875s][info][gc,remset ] GC(15) max_clean_run: [ 0.00 0.00 0.00 0.00 100.00 ]
> [631.875s][info][gc,remset ] GC(15) dirty_objs: [ 0.00 230.47 818.36 871.09 1366.00 ]
> [631.875s][info][gc,remset ] GC(15) clean_objs: [ 0.00 0.00 0.00 0.00 63.00 ]
> [631.875s][info][gc,remset ] GC(15) dirty_scans: [ 0.00 181.64 707.03 796.88 1365.00 ]
> [631.875s][info][gc,remset ] GC(15) clean_scans: [ 0.00 0.00 0.00 0.00 16.00 ]
> [631.875s][info][gc,remset ] GC(15) alternations: [ 0.00 0.00 0.00 0.00 33.00 ]
> [631.876s][info][gc,remset ] GC(15) Cumulative stats
> [631.876s][info][gc,remset ] GC(15) dirty_run: [ 0.00 0.00 0.00 6.25 100.00 ]
> [631.876s][info][gc,remset ] GC(15) clean_run: [ 0.00 0.00 0.00 1.56 100.00 ]
> [631.876s][info][gc,remset ] GC(15) dirty_cards: [ 0.00 32.81 99.61 99.61 100.00 ]
> [631.876s][info][gc,remset ] GC(15) clean_cards: [ 0.00 0.00 0.00 43.75 100.00 ]
> [631.876s][info][gc,remset ] GC(15) max_dirty_run: [ 0.00 15.62 99.61 99.61 100.00 ]
> [631.876s][info][gc,remset ] GC(15) max_clean_run: [ 0.00 0.00 0.00 20.31 100.00 ]
> [631.876s][info][gc,remset ] GC(15) dirty_objs: [ 0.00 0.00 20.90 695.31 1366.00 ]
> [631.876s][info][gc,remset ] GC(15) clean_objs: [ 0.00 0.00 0.00 11.91 64.00 ]
> [631.876s][info][gc,remset ] GC(15) dirty_scans: [ 0.00 0.00 11.91 562.50 1365.00 ]
> [631.876s][info][gc,remset ] GC(15) clean_scans: [ 0.00 0.00 0.00 0.00 16.00 ]
> [631.876s][info][gc,remset ] GC(15) alternations: [ 0.00 0.00 0.00 0.00 33.00 ]
> [631.876s][info][gc ] GC(15) Concurrent update references 1953.893ms
> ...
>
>
> The rows represent the metric that's being tracked, and the columns are, respectively, minimum, the 3 quartiles (25%, 50%, 75%) and the maximum. The metrics are:
>
> - dirty_run: the length of an uninterrupted run of dirty cards, interpretedas a percentage of a chunk of work assignment (cluster) processed by a thread
> - clean_run: as above, but the length of an uninterrupted run of clean cards
> - dirty_cards, clean_cards: as above, but counts of cards as a percentage of chunk
> - max_dirty_run & max_clean_run: Similarly for the maximum of each.
> - dirty_objs, clean_objs: these are numbers of objects in any chunk walked, or scanned
> - dirty_scans, clean_scans: numbers of objects scanned by the closure
> - alternations: the number of times that we transitioned from clean to dirty or dirty to clean in a chunk
>
> For example, the last cumulative log data (for UR) above indicates that at least 75% of the chunks have no alternations at all,
> and cards are almost always mostly clean for this specific prefix of the run.
>
> Comparing worker stats from worker 0 and worker 1 indicates that in particular scans they may see different distributions of dirty cards for specific benchmarks based on their promotion and mutation behavior.
>
> **Question:**
> Would it make sense to print also, for example, the 1, 10, 90 and 99 percentiles for these metrics as well, in addition to the quartiles, min, and max?
Y. Srinivas Ramakrishna has updated the pull request incrementally with one additional commit since the last revision:
A couple of changes based on review feedback.
-------------
Changes:
- all: https://git.openjdk.org/shenandoah/pull/176/files
- new: https://git.openjdk.org/shenandoah/pull/176/files/1bc59f89..bfddb220
Webrevs:
- full: https://webrevs.openjdk.org/?repo=shenandoah&pr=176&range=13
- incr: https://webrevs.openjdk.org/?repo=shenandoah&pr=176&range=12-13
Stats: 3 lines in 2 files changed: 1 ins; 0 del; 2 mod
Patch: https://git.openjdk.org/shenandoah/pull/176.diff
Fetch: git fetch https://git.openjdk.org/shenandoah pull/176/head:pull/176
PR: https://git.openjdk.org/shenandoah/pull/176
More information about the shenandoah-dev
mailing list