RFR: JDK-8297796 GenShen: instrument the remembered set scan [v15]
Y. Srinivas Ramakrishna
ysr at openjdk.org
Thu Dec 22 04:34:00 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 with a new target base due to a merge or a rebase. The pull request now contains 68 commits:
- Merge branch 'master' into JVM-1264
- A couple of changes based on review feedback.
- Reword some code comments for greater clarity.
- Merge branch 'master' into JVM-1264-dependent
- Add a previously missed ticket#. Doing it here rather than in parent to
avoid an otherwise unnecessary re-review touchpoint.
- Merge branch 'stats_merge' into JVM-1264-dependent
- Merge branch 'master' into stats_merge
- jcheck space fix
- Fix compiler error on windows.
- Fix some tier1 tests.
- ... and 58 more: https://git.openjdk.org/shenandoah/compare/d793fd16...4e5ad4ca
-------------
Changes: https://git.openjdk.org/shenandoah/pull/176/files
Webrev: https://webrevs.openjdk.org/?repo=shenandoah&pr=176&range=14
Stats: 865 lines in 9 files changed: 496 ins; 206 del; 163 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