Hi all,
I would really appreciate some help understanding a G1 behaviour I am
seeing when decreasing the value of G1RSetUpdatingPauseTimePercent where
the goal is to decrease the time spent in the UpdateRS phase by moving some
of the work to be processed concurrently by the refinement threads.
The behaviour I was expecting to see was a decrease in UpdateRS time which
I am seeing but at the expense of more time being spent in the ScanRS phase
so the end result i.e. the total pause time end up being very similar with
and without the flag set. Decreasing G1RSetUpdatingPauseTimePercent to both
5 and 1 results in similar behaviour. I noticed that the number of scanned
cards is much higher in the ScanRS phase when decreasing
G1RSetUpdatingPauseTimePercent.
Is this expected behaviour?
Are there any other flags worth considering to improve the ScanRS time
while moving more work to the refinement threads?
JVM flags and gc logs with and without the flag set can be found below.
Thanks,
Joakim
*JVM flags:*
-XX:-G1UseAdaptiveIHOP
-Xms16g
-Xmx16g
-XX:ParallelGCThreads=15
-XX:+DisableExplicitGC
-XX:+AlwaysPreTouch
-XX:+UseG1GC
-XX:G1HeapRegionSize=16M
*Base line gc logs ( without setting G1RSetUpdatingPauseTimePercent ):*
[2020-01-17T14:35:39.003+0000][1419.301s][30887] GC(136) Pause Young
(Normal) (G1 Evacuation Pause)
[2020-01-17T14:35:39.003+0000][1419.301s][30887] GC(136) Using 15 workers
of 15 for evacuation
[2020-01-17T14:35:39.031+0000][1419.329s][30887] GC(136) Pre Evacuate
Collection Set: 0.0ms
[2020-01-17T14:35:39.031+0000][1419.329s][30887] GC(136) Prepare TLABs:
0.1ms
[2020-01-17T14:35:39.031+0000][1419.329s][30887] GC(136) Choose
Collection Set: 0.0ms
[2020-01-17T14:35:39.031+0000][1419.329s][30887] GC(136) Humongous
Register: 0.0ms
[2020-01-17T14:35:39.031+0000][1419.329s][30887] GC(136) Evacuate
Collection Set: 25.6ms
[2020-01-17T14:35:39.031+0000][1419.329s][30887] GC(136) Ext Root
Scanning (ms): Min: 0.8, Avg: 1.1, Max: 1.2, Diff: 0.3, Sum: 16.5,
Workers: 15
[2020-01-17T14:35:39.031+0000][1419.329s][30887] GC(136) Update RS
(ms): Min: 10.2, Avg: 12.5, Max: 13.4, Diff: 3.2, Sum: 187.8,
Workers: 15
[2020-01-17T14:35:39.031+0000][1419.329s][30887] GC(136) Processed
Buffers: Min: 30, Avg: 57.1, Max: 87, Diff: 57, Sum: 856, Workers: 15
[2020-01-17T14:35:39.031+0000][1419.329s][30887] GC(136) Scanned
Cards: Min: 6490, Avg: 10050.3, Max: 12584, Diff: 6094, Sum:
150754, Workers: 15
[2020-01-17T14:35:39.031+0000][1419.329s][30887] GC(136) Skipped
Cards: Min: 0, Avg: 3.7, Max: 10, Diff: 10, Sum: 56, Workers: 15
[2020-01-17T14:35:39.031+0000][1419.329s][30887] GC(136) Scan RS (ms):
Min: 0.0, Avg: 0.3, Max: 0.4, Diff: 0.4, Sum: 4.3,
Workers: 15
[2020-01-17T14:35:39.031+0000][1419.329s][30887] GC(136) Scanned
Cards: Min: 0, Avg: 139.5, Max: 287, Diff: 287, Sum: 2092,
Workers: 15
[2020-01-17T14:35:39.031+0000][1419.329s][30887] GC(136) Claimed
Cards: Min: 0, Avg: 140.3, Max: 287, Diff: 287, Sum: 2104,
Workers: 15
[2020-01-17T14:35:39.031+0000][1419.329s][30887] GC(136) Skipped
Cards: Min: 0, Avg: 1642.5, Max: 1881, Diff: 1881, Sum: 24638,
Workers: 15
[2020-01-17T14:35:39.031+0000][1419.329s][30887] GC(136) Code Root
Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.3, Diff: 0.3, Sum: 0.3,
Workers: 15
[2020-01-17T14:35:39.031+0000][1419.329s][30887] GC(136) AOT Root
Scanning (ms): skipped
[2020-01-17T14:35:39.031+0000][1419.329s][30887] GC(136) Object Copy
(ms): Min: 10.5, Avg: 11.5, Max: 14.1, Diff: 3.6, Sum: 172.8,
Workers: 15
[2020-01-17T14:35:39.031+0000][1419.329s][30887] GC(136) Termination
(ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0,
Workers: 15
[2020-01-17T14:35:39.031+0000][1419.329s][30887] GC(136) Termination
Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 15, Workers: 15
[2020-01-17T14:35:39.031+0000][1419.329s][30887] GC(136) GC Worker
Other (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 1.2,
Workers: 15
[2020-01-17T14:35:39.031+0000][1419.329s][30887] GC(136) GC Worker
Total (ms): Min: 25.5, Avg: 25.5, Max: 25.6, Diff: 0.0, Sum: 383.1,
Workers: 15
[2020-01-17T14:35:39.032+0000][1419.329s][30887] GC(136) Post Evacuate
Collection Set: 1.6ms
[2020-01-17T14:35:39.032+0000][1419.329s][30887] GC(136) Code Roots
Fixup: 0.0ms
[2020-01-17T14:35:39.032+0000][1419.329s][30887] GC(136) Clear Card
Table: 0.6ms
[2020-01-17T14:35:39.032+0000][1419.329s][30887] GC(136) Reference
Processing: 0.2ms
[2020-01-17T14:35:39.032+0000][1419.329s][30887] GC(136) Weak
Processing: 0.1ms
[2020-01-17T14:35:39.032+0000][1419.329s][30887] GC(136) Merge
Per-Thread State: 0.0ms
[2020-01-17T14:35:39.032+0000][1419.329s][30887] GC(136) Code Roots
Purge: 0.0ms
[2020-01-17T14:35:39.032+0000][1419.329s][30887] GC(136) Redirty Cards:
0.3ms
[2020-01-17T14:35:39.032+0000][1419.329s][30887] GC(136)
DerivedPointerTable Update: 0.2ms
[2020-01-17T14:35:39.032+0000][1419.329s][30887] GC(136) Free
Collection Set: 0.3ms
[2020-01-17T14:35:39.032+0000][1419.329s][30887] GC(136) Humongous
Reclaim: 0.0ms
[2020-01-17T14:35:39.032+0000][1419.329s][30887] GC(136) Start New
Collection Set: 0.0ms
[2020-01-17T14:35:39.032+0000][1419.329s][30887] GC(136) Resize TLABs:
0.1ms
[2020-01-17T14:35:39.032+0000][1419.329s][30887] GC(136) Expand Heap
After Collection: 0.0ms
[2020-01-17T14:35:39.032+0000][1419.329s][30887] GC(136) Other: 0.9ms
[2020-01-17T14:35:39.032+0000][1419.329s][30887] GC(136) Eden regions:
609->0(609)
[2020-01-17T14:35:39.032+0000][1419.329s][30887] GC(136) Survivor regions:
5->5(77)
[2020-01-17T14:35:39.032+0000][1419.329s][30887] GC(136) Old regions:
125->125
[2020-01-17T14:35:39.032+0000][1419.329s][30887] GC(136) Humongous regions:
2->2
[2020-01-17T14:35:39.032+0000][1419.329s][30887] GC(136) Metaspace:
147406K->147406K(1183744K)
[2020-01-17T14:35:39.032+0000][1419.329s][30887] GC(136) Pause Young
(Normal) (G1 Evacuation Pause) 11839M->2097M(16384M) 28.293ms
With G1RSetUpdatingPauseTimePercent set to 1:
[2020-01-17T17:46:58.485+0000][554.067s][18852] Entering safepoint region:
G1CollectForAllocation
[2020-01-17T17:46:58.486+0000][554.067s][18852] GC(65) Pause Young (Normal)
(G1 Evacuation Pause)
[2020-01-17T17:46:58.486+0000][554.067s][18852] GC(65) Using 15 workers of
15 for evacuation
[2020-01-17T17:46:58.486+0000][554.067s][18852] GC(65) Before GC RS summary
[2020-01-17T17:46:58.486+0000][554.067s][18852] GC(65) Recent concurrent
refinement statistics
[2020-01-17T17:46:58.486+0000][554.067s][18852] GC(65) Processed 224586
cards concurrently
[2020-01-17T17:46:58.486+0000][554.067s][18852] GC(65) Of 1084 completed
buffers:
[2020-01-17T17:46:58.486+0000][554.067s][18852] GC(65) 1084
(100.0%) by concurrent RS threads.
[2020-01-17T17:46:58.486+0000][554.067s][18852] GC(65) 0 (
0.0%) by mutator threads.
[2020-01-17T17:46:58.486+0000][554.067s][18852] GC(65) Did 0 coarsenings.
[2020-01-17T17:46:58.486+0000][554.067s][18852] GC(65) Concurrent RS
threads times (s)
[2020-01-17T17:46:58.486+0000][554.067s][18852] GC(65) 0.07
0.06 0.05 0.04 0.04 0.04 0.04 0.02 0.02
0.02 0.01 0.00 0.02 0.01 0.01
[2020-01-17T17:46:58.486+0000][554.067s][18852] GC(65) Concurrent
sampling threads times (s)
[2020-01-17T17:46:58.486+0000][554.067s][18852] GC(65) 0.01
[2020-01-17T17:46:58.487+0000][554.068s][18852] GC(65) Current rem set
statistics
[2020-01-17T17:46:58.487+0000][554.068s][18852] GC(65) Total per region
rem sets sizes = 13401K. Max = 498K.
[2020-01-17T17:46:58.487+0000][554.068s][18852] GC(65) 8722K (
65.1%) by 614 Young regions
[2020-01-17T17:46:58.487+0000][554.068s][18852] GC(65) 18384B (
0.1%) by 2 Humongous regions
[2020-01-17T17:46:58.487+0000][554.068s][18852] GC(65) 2719K (
20.3%) by 303 Free regions
[2020-01-17T17:46:58.487+0000][554.068s][18852] GC(65) 1941K (
14.5%) by 105 Old regions
[2020-01-17T17:46:58.487+0000][554.068s][18852] GC(65) Static structures
= 520K, free_lists = 4826K.
[2020-01-17T17:46:58.487+0000][554.068s][18852] GC(65) 120031 occupied
cards represented.
[2020-01-17T17:46:58.487+0000][554.068s][18852] GC(65) 120030
(100.0%) entries by 614 Young regions
[2020-01-17T17:46:58.487+0000][554.068s][18852] GC(65) 1 (
0.0%) entries by 2 Humongous regions
[2020-01-17T17:46:58.487+0000][554.068s][18852] GC(65) 0 (
0.0%) entries by 303 Free regions
[2020-01-17T17:46:58.487+0000][554.068s][18852] GC(65) 0 (
0.0%) entries by 105 Old regions
[2020-01-17T17:46:58.487+0000][554.068s][18852] GC(65) Region with
largest rem set =
7:(O)[0x0000000407000000,0x0000000408000000,0x0000000408000000], size =
498K, occupied = 0B.
[2020-01-17T17:46:58.487+0000][554.068s][18852] GC(65) Total heap region
code root sets sizes = 1021K. Max = 489K.
[2020-01-17T17:46:58.487+0000][554.068s][18852] GC(65) 16280B (
1.6%) by 614 Young regions
[2020-01-17T17:46:58.487+0000][554.068s][18852] GC(65) 32B (
0.0%) by 2 Humongous regions
[2020-01-17T17:46:58.487+0000][554.068s][18852] GC(65) 4848B (
0.5%) by 303 Free regions
[2020-01-17T17:46:58.487+0000][554.068s][18852] GC(65) 1000K (
98.0%) by 105 Old regions
[2020-01-17T17:46:58.487+0000][554.068s][18852] GC(65) 37574 code roots
represented.
[2020-01-17T17:46:58.487+0000][554.068s][18852] GC(65) 83 (
0.2%) elements by 614 Young regions
[2020-01-17T17:46:58.487+0000][554.068s][18852] GC(65) 0 (
0.0%) elements by 2 Humongous regions
[2020-01-17T17:46:58.487+0000][554.068s][18852] GC(65) 0 (
0.0%) elements by 303 Free regions
[2020-01-17T17:46:58.487+0000][554.068s][18852] GC(65) 37491 (
99.8%) elements by 105 Old regions
[2020-01-17T17:46:58.487+0000][554.068s][18852] GC(65) Region with
largest amount of code roots =
7:(O)[0x0000000407000000,0x0000000408000000,0x0000000408000000], size =
489K, num_elems = 20702.
[2020-01-17T17:46:58.516+0000][554.097s][18852] GC(65) After GC RS summary
[2020-01-17T17:46:58.516+0000][554.097s][18852] GC(65) Recent concurrent
refinement statistics
[2020-01-17T17:46:58.516+0000][554.097s][18852] GC(65) Processed 0 cards
concurrently
[2020-01-17T17:46:58.516+0000][554.097s][18852] GC(65) Of 407 completed
buffers:
[2020-01-17T17:46:58.516+0000][554.097s][18852] GC(65) 407
(100.0%) by concurrent RS threads.
[2020-01-17T17:46:58.516+0000][554.097s][18852] GC(65) 0 (
0.0%) by mutator threads.
[2020-01-17T17:46:58.516+0000][554.097s][18852] GC(65) Did 0 coarsenings.
[2020-01-17T17:46:58.516+0000][554.097s][18852] GC(65) Concurrent RS
threads times (s)
[2020-01-17T17:46:58.516+0000][554.097s][18852] GC(65) 0.00
0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
0.00 0.00 0.00 0.00 0.00 0.00
[2020-01-17T17:46:58.516+0000][554.097s][18852] GC(65) Concurrent
sampling threads times (s)
[2020-01-17T17:46:58.516+0000][554.097s][18852] GC(65) 0.00
[2020-01-17T17:46:58.516+0000][554.097s][18852] GC(65) Current rem set
statistics
[2020-01-17T17:46:58.516+0000][554.097s][18852] GC(65) Total per region
rem sets sizes = 10206K. Max = 498K.
[2020-01-17T17:46:58.516+0000][554.097s][18852] GC(65) 57200B (
0.5%) by 5 Young regions
[2020-01-17T17:46:58.516+0000][554.097s][18852] GC(65) 18384B (
0.2%) by 2 Humongous regions
[2020-01-17T17:46:58.516+0000][554.097s][18852] GC(65) 8186K (
80.2%) by 912 Free regions
[2020-01-17T17:46:58.516+0000][554.097s][18852] GC(65) 1945K (
19.1%) by 105 Old regions
[2020-01-17T17:46:58.516+0000][554.098s][18852] GC(65) Static structures
= 520K, free_lists = 7548K.
[2020-01-17T17:46:58.516+0000][554.098s][18852] GC(65) 206 occupied
cards represented.
[2020-01-17T17:46:58.516+0000][554.098s][18852] GC(65) 205 (
99.5%) entries by 5 Young regions
[2020-01-17T17:46:58.516+0000][554.098s][18852] GC(65) 1 (
0.5%) entries by 2 Humongous regions
[2020-01-17T17:46:58.516+0000][554.098s][18852] GC(65) 0 (
0.0%) entries by 912 Free regions
[2020-01-17T17:46:58.516+0000][554.098s][18852] GC(65) 0 (
0.0%) entries by 105 Old regions
[2020-01-17T17:46:58.516+0000][554.098s][18852] GC(65) Region with
largest rem set =
7:(O)[0x0000000407000000,0x0000000408000000,0x0000000408000000], size =
498K, occupied = 0B.
[2020-01-17T17:46:58.516+0000][554.098s][18852] GC(65) Total heap region
code root sets sizes = 1024K. Max = 489K.
[2020-01-17T17:46:58.516+0000][554.098s][18852] GC(65) 5816B (
0.6%) by 5 Young regions
[2020-01-17T17:46:58.516+0000][554.098s][18852] GC(65) 32B (
0.0%) by 2 Humongous regions
[2020-01-17T17:46:58.516+0000][554.098s][18852] GC(65) 14592B (
1.4%) by 912 Free regions
[2020-01-17T17:46:58.516+0000][554.098s][18852] GC(65) 1004K (
98.1%) by 105 Old regions
[2020-01-17T17:46:58.516+0000][554.098s][18852] GC(65) 37573 code roots
represented.
[2020-01-17T17:46:58.516+0000][554.098s][18852] GC(65) 66 (
0.2%) elements by 5 Young regions
[2020-01-17T17:46:58.516+0000][554.098s][18852] GC(65) 0 (
0.0%) elements by 2 Humongous regions
[2020-01-17T17:46:58.516+0000][554.098s][18852] GC(65) 0 (
0.0%) elements by 912 Free regions
[2020-01-17T17:46:58.516+0000][554.098s][18852] GC(65) 37507 (
99.8%) elements by 105 Old regions
[2020-01-17T17:46:58.516+0000][554.098s][18852] GC(65) Region with
largest amount of code roots =
7:(O)[0x0000000407000000,0x0000000408000000,0x0000000408000000], size =
489K, num_elems = 20702.
[2020-01-17T17:46:58.516+0000][554.098s][18852] GC(65) Pre Evacuate
Collection Set: 0.0ms
[2020-01-17T17:46:58.516+0000][554.098s][18852] GC(65) Prepare TLABs:
0.1ms
[2020-01-17T17:46:58.516+0000][554.098s][18852] GC(65) Choose
Collection Set: 0.0ms
[2020-01-17T17:46:58.516+0000][554.098s][18852] GC(65) Humongous
Register: 0.0ms
[2020-01-17T17:46:58.516+0000][554.098s][18852] GC(65) Evacuate
Collection Set: 26.0ms
[2020-01-17T17:46:58.516+0000][554.098s][18852] GC(65) Ext Root
Scanning (ms): Min: 0.7, Avg: 1.2, Max: 1.3, Diff: 0.6, Sum: 17.3,
Workers: 15
[2020-01-17T17:46:58.516+0000][554.098s][18852] GC(65) Update RS (ms):
Min: 0.8, Avg: 2.4, Max: 3.8, Diff: 3.0, Sum: 35.4, Workers:
15
[2020-01-17T17:46:58.516+0000][554.098s][18852] GC(65) Processed
Buffers: Min: 4, Avg: 27.1, Max: 68, Diff: 64, Sum: 407, Workers: 15
[2020-01-17T17:46:58.516+0000][554.098s][18852] GC(65) Scanned Cards:
Min: 503, Avg: 1842.7, Max: 3156, Diff: 2653, Sum: 27641,
Workers: 15
[2020-01-17T17:46:58.516+0000][554.098s][18852] GC(65) Skipped Cards:
Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 15
[2020-01-17T17:46:58.516+0000][554.098s][18852] GC(65) Scan RS (ms):
Min: 2.9, Avg: 9.1, Max: 12.6, Diff: 9.6, Sum: 136.8, Workers:
15
[2020-01-17T17:46:58.516+0000][554.098s][18852] GC(65) Scanned Cards:
Min: 557, Avg: 4460.7, Max: 7315, Diff: 6758, Sum: 66910,
Workers: 15
[2020-01-17T17:46:58.516+0000][554.098s][18852] GC(65) Claimed Cards:
Min: 1152, Avg: 8002.0, Max: 12274, Diff: 11122, Sum: 120030,
Workers: 15
[2020-01-17T17:46:58.516+0000][554.098s][18852] GC(65) Skipped Cards:
Min: 35295, Avg: 61708.5, Max: 70294, Diff: 34999, Sum: 925628,
Workers: 15
[2020-01-17T17:46:58.516+0000][554.098s][18852] GC(65) Code Root
Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.6, Diff: 0.6, Sum: 0.7,
Workers: 15
[2020-01-17T17:46:58.516+0000][554.098s][18852] GC(65) AOT Root
Scanning (ms): skipped
[2020-01-17T17:46:58.516+0000][554.098s][18852] GC(65) Object Copy
(ms): Min: 9.0, Avg: 13.1, Max: 21.2, Diff: 12.2, Sum: 197.0,
Workers: 15
[2020-01-17T17:46:58.516+0000][554.098s][18852] GC(65) Termination
(ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0,
Workers: 15
[2020-01-17T17:46:58.516+0000][554.098s][18852] GC(65) Termination
Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 15, Workers: 15
[2020-01-17T17:46:58.516+0000][554.098s][18852] GC(65) GC Worker Other
(ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.0, Sum: 0.9, Workers:
15
[2020-01-17T17:46:58.516+0000][554.098s][18852] GC(65) GC Worker Total
(ms): Min: 26.0, Avg: 26.0, Max: 26.0, Diff: 0.0, Sum: 389.6, Workers:
15
[2020-01-17T17:46:58.517+0000][554.098s][18852] GC(65) Post Evacuate
Collection Set: 1.9ms
[2020-01-17T17:46:58.517+0000][554.098s][18852] GC(65) Code Roots
Fixup: 0.0ms
[2020-01-17T17:46:58.517+0000][554.098s][18852] GC(65) Clear Card
Table: 0.9ms
[2020-01-17T17:46:58.517+0000][554.098s][18852] GC(65) Reference
Processing: 0.3ms
[2020-01-17T17:46:58.517+0000][554.098s][18852] GC(65) Weak Processing:
0.1ms
[2020-01-17T17:46:58.517+0000][554.098s][18852] GC(65) Merge Per-Thread
State: 0.0ms
[2020-01-17T17:46:58.517+0000][554.098s][18852] GC(65) Code Roots
Purge: 0.0ms
[2020-01-17T17:46:58.517+0000][554.098s][18852] GC(65) Redirty Cards:
0.2ms
[2020-01-17T17:46:58.517+0000][554.098s][18852] GC(65)
DerivedPointerTable Update: 0.2ms
[2020-01-17T17:46:58.517+0000][554.098s][18852] GC(65) Free Collection
Set: 0.4ms
[2020-01-17T17:46:58.517+0000][554.098s][18852] GC(65) Humongous
Reclaim: 0.0ms
[2020-01-17T17:46:58.517+0000][554.098s][18852] GC(65) Start New
Collection Set: 0.0ms
[2020-01-17T17:46:58.517+0000][554.098s][18852] GC(65) Resize TLABs:
0.1ms
[2020-01-17T17:46:58.517+0000][554.098s][18852] GC(65) Expand Heap
After Collection: 0.0ms
[2020-01-17T17:46:58.517+0000][554.098s][18852] GC(65) Other: 2.6ms
[2020-01-17T17:46:58.517+0000][554.098s][18852] GC(65) Eden regions:
609->0(609)
[2020-01-17T17:46:58.517+0000][554.098s][18852] GC(65) Survivor regions:
5->5(77)
[2020-01-17T17:46:58.517+0000][554.098s][18852] GC(65) Old regions: 105->105
[2020-01-17T17:46:58.517+0000][554.098s][18852] GC(65) Humongous regions:
2->2
[2020-01-17T17:46:58.517+0000][554.098s][18852] GC(65) Metaspace:
144342K->144342K(1179648K)
[2020-01-17T17:46:58.517+0000][554.098s][18852] GC(65) Pause Young (Normal)
(G1 Evacuation Pause) 11526M->1789M(16384M) 30.664ms
_______________________________________________
hotspot-gc-use mailing list
hotspot-gc-use@openjdk.java.net
https://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use
