Long pause for processing weakrefs in DaCapo benchmark
raell at web.de
raell at web.de
Mon May 18 01:16:29 UTC 2020
Hi all,
I'm evaluating runtime and pauses for various GCs using the DaCapo benchmark suite. For
benchmark "tradesoap" I observe a long maximal pause time in Shenandoah. As an example,
from a run using default parameters for each GC:
Runtime: 43s (Shenandoah), 34s (ZGC), 25s (Parallel), 26s (G1)
Max Pause: 147ms (Shenandoah), 8.8ms (ZGC), 123ms (Parallel), 109ms (G1)
The long pause results from weakrefs processing. I've been varying several parameters
like ShenandoahMinFreeThreshold, ShenandoahSATBBufferSize, ShenandoahRefProcFrequency,
or setting +ClassUnloadingWithConcurrentMark or +UseNUMA. But it didn't improve much.
For instance, with ShenandoahMinFreeThreshold=90 the max pause reduced to 80ms (and
the runtime increased for 20%).
Below there is an output from two runs, one with class unloading enabled and one with
class unloading disabled.
Is there a parameter that can be set or something else what can be done to reduce the
maximal pause time significantly?
BTW: For the other benchmarks in the suite, the max pause looks fine (around 10ms or lower).
Thanks and best regards
Ralph
The benchmark has been runing on Debian using AdoptOpenJDK jdk-14+36.
Hardware: 6 cores, 16GB RAM.
-------------------------------------------------------------------------------------------
1. Example: class unloading enabled
yields: Pause Final Mark (update refs) (process weakrefs) (unload classes) 172.116ms
-------------------------------------------------------------------------------------------
java -Xms1G -Xmx1G -XX:+AlwaysPreTouch \
-Xlog:gc,gc+stats \
-XX:+UnlockExperimentalVMOptions \
-XX:+UseShenandoahGC \
-XX:ShenandoahMinFreeThreshold=25 \
-jar dacapo-9.12-MR1-bach.jar tradesoap -s large --no-pre-iteration-gc -9 >> $logfile 2>&1
[2.081s][info][gc] Using Shenandoah
Using scaled threading model. 6 processors detected, 6 threads used to drive the workload, in a possible range of [1,512]
...
[327.215s][info][gc] Trigger: Free (200M) is below minimum threshold (255M)
[327.218s][info][gc] GC(445) Concurrent reset 814M->815M(1024M) 2.831ms
[327.220s][info][gc] GC(445) Pause Init Mark (update refs) (process weakrefs) (unload classes) 1.187ms
[327.459s][info][gc] GC(445) Concurrent marking (update refs) (process weakrefs) (unload classes) 815M->837M(1024M) 238.509ms
[327.466s][info][gc] GC(445) Concurrent precleaning 837M->839M(1024M) 6.704ms
[327.639s][info][gc] GC(445) Pause Final Mark (update refs) (process weakrefs) (unload classes) 172.116ms
[327.680s][info][gc] GC(445) Concurrent roots processing 839M->867M(1024M) 40.903ms
[327.681s][info][gc] GC(445) Concurrent cleanup 866M->592M(1024M) 0.722ms
[327.751s][info][gc] GC(445) Concurrent evacuation 592M->633M(1024M) 69.871ms
[327.752s][info][gc] GC(445) Pause Init Update Refs 0.174ms
[327.972s][info][gc] GC(445) Concurrent update references 633M->710M(1024M) 219.948ms
[327.974s][info][gc] GC(445) Pause Final Update Refs 0.658ms
[327.974s][info][gc] GC(445) Concurrent cleanup 710M->503M(1024M) 0.139ms
...
[411.436s][info][gc,stats] Total Pauses (G) = 14.56 s (a = 7549 us) (n = 1929) (lvls, us = 723, 1328, 2461, 3633, 173731)
[411.436s][info][gc,stats] Total Pauses (N) = 12.26 s (a = 6356 us) (n = 1929) (lvls, us = 42, 189, 1367, 2402, 172170)
[411.436s][info][gc,stats] Pause Init Mark (G) = 1.64 s (a = 2862 us) (n = 572) (lvls, us = 1836, 2324, 2559, 2930, 17977)
[411.436s][info][gc,stats] Pause Init Mark (N) = 0.95 s (a = 1658 us) (n = 572) (lvls, us = 941, 1309, 1504, 1777, 10139)
[411.436s][info][gc,stats] Make Parsable = 0.04 s (a = 69 us) (n = 572) (lvls, us = 8, 49, 64, 81, 416)
[411.436s][info][gc,stats] Clear Liveness = 0.08 s (a = 146 us) (n = 572) (lvls, us = 63, 113, 127, 145, 4013)
[411.436s][info][gc,stats] Scan Roots = 0.76 s (a = 1337 us) (n = 572) (lvls, us = 709, 1016, 1211, 1465, 5861)
[411.436s][info][gc,stats] S: Thread Roots = 0.39 s (a = 686 us) (n = 572) (lvls, us = 438, 576, 652, 750, 3095)
[411.436s][info][gc,stats] S: Universe Roots = 0.00 s (a = 4 us) (n = 572) (lvls, us = 2, 3, 4, 5, 50)
[411.436s][info][gc,stats] S: JNI Roots = 0.00 s (a = 1 us) (n = 572) (lvls, us = 1, 1, 1, 1, 26)
[411.436s][info][gc,stats] S: VM Global Roots = 0.00 s (a = 0 us) (n = 572) (lvls, us = 0, 0, 0, 0, 0)
[411.436s][info][gc,stats] S: Synchronizer Roots = 0.00 s (a = 0 us) (n = 572) (lvls, us = 0, 0, 0, 0, 9)
[411.436s][info][gc,stats] S: Management Roots = 0.00 s (a = 4 us) (n = 572) (lvls, us = 2, 3, 3, 4, 72)
[411.436s][info][gc,stats] S: System Dict Roots = 0.01 s (a = 12 us) (n = 572) (lvls, us = 7, 10, 12, 14, 92)
[411.436s][info][gc,stats] S: CLDG Roots = 0.08 s (a = 133 us) (n = 572) (lvls, us = 65, 100, 123, 152, 1273)
[411.436s][info][gc,stats] S: JVMTI Roots = 0.00 s (a = 1 us) (n = 572) (lvls, us = 0, 1, 1, 1, 37)
[411.436s][info][gc,stats] Resize TLABs = 0.02 s (a = 31 us) (n = 572) (lvls, us = 6, 22, 28, 34, 175)
[411.436s][info][gc,stats] Pause Final Mark (G) = 11.74 s (a = 20527 us) (n = 572) (lvls, us = 2363, 3516, 4160, 7207, 173729)
[411.436s][info][gc,stats] Pause Final Mark (N) = 11.03 s (a = 19281 us) (n = 572) (lvls, us = 1621, 2461, 3027, 5840, 172169)
[411.436s][info][gc,stats] Update Roots = 0.27 s (a = 747 us) (n = 359) (lvls, us = 396, 594, 715, 838, 2452)
[411.436s][info][gc,stats] U: Thread Roots = 0.18 s (a = 507 us) (n = 359) (lvls, us = 328, 426, 482, 561, 1744)
[411.436s][info][gc,stats] Finish Queues = 0.47 s (a = 822 us) (n = 572) (lvls, us = 76, 170, 223, 295, 63181)
[411.436s][info][gc,stats] Weak References = 9.07 s (a = 77487 us) (n = 117) (lvls, us = 154, 69531, 76562, 90039, 167547)
[411.436s][info][gc,stats] Process = 9.06 s (a = 77477 us) (n = 117) (lvls, us = 42, 69531, 76562, 90039, 167539)
[411.436s][info][gc,stats] System Purge = 0.22 s (a = 380 us) (n = 572) (lvls, us = 174, 283, 342, 418, 6337)
[411.436s][info][gc,stats] Parallel Cleanup = 0.22 s (a = 378 us) (n = 572) (lvls, us = 174, 281, 340, 416, 6333)
[411.436s][info][gc,stats] Complete Liveness = 0.06 s (a = 96 us) (n = 572) (lvls, us = 45, 71, 88, 104, 1024)
[411.436s][info][gc,stats] Retire TLABs = 0.04 s (a = 74 us) (n = 572) (lvls, us = 12, 59, 67, 84, 328)
[411.436s][info][gc,stats] Sync Pinned = 0.02 s (a = 33 us) (n = 572) (lvls, us = 11, 26, 28, 37, 508)
[411.436s][info][gc,stats] Trash CSet = 0.01 s (a = 15 us) (n = 572) (lvls, us = 2, 3, 16, 23, 130)
[411.436s][info][gc,stats] Prepare Evacuation = 0.19 s (a = 326 us) (n = 572) (lvls, us = 123, 266, 316, 363, 1330)
[411.436s][info][gc,stats] Initial Evacuation = 0.63 s (a = 1107 us) (n = 572) (lvls, us = 600, 885, 1016, 1191, 6153)
[411.436s][info][gc,stats] E: Thread Roots = 0.36 s (a = 625 us) (n = 572) (lvls, us = 332, 502, 588, 693, 3142)
[411.436s][info][gc,stats] E: Universe Roots = 0.00 s (a = 2 us) (n = 572) (lvls, us = 1, 1, 2, 2, 34)
[411.436s][info][gc,stats] E: JVMTI Weak Roots = 0.00 s (a = 0 us) (n = 572) (lvls, us = 0, 0, 0, 0, 3)
[411.436s][info][gc,stats] E: JFR Weak Roots = 0.00 s (a = 1 us) (n = 572) (lvls, us = 0, 0, 0, 1, 3)
[411.436s][info][gc,stats] E: Synchronizer Roots = 0.00 s (a = 0 us) (n = 572) (lvls, us = 0, 0, 0, 1, 15)
[411.436s][info][gc,stats] E: Management Roots = 0.00 s (a = 3 us) (n = 572) (lvls, us = 1, 2, 2, 3, 19)
[411.436s][info][gc,stats] E: System Dict Roots = 0.00 s (a = 8 us) (n = 572) (lvls, us = 5, 6, 7, 8, 32)
[411.437s][info][gc,stats] E: JVMTI Roots = 0.00 s (a = 1 us) (n = 572) (lvls, us = 1, 1, 1, 1, 5)
[411.437s][info][gc,stats] Pause Final Evac (G) = 0.43 s (a = 1198 us) (n = 359) (lvls, us = 785, 965, 1074, 1191, 7463)
[411.437s][info][gc,stats] Pause Final Evac (N) = 0.03 s (a = 84 us) (n = 359) (lvls, us = 42, 74, 81, 90, 561)
[411.437s][info][gc,stats] Retire GCLABs = 0.01 s (a = 38 us) (n = 359) (lvls, us = 17, 32, 37, 40, 403)
[411.437s][info][gc,stats] Pause Init Update Refs (G) = 0.28 s (a = 1313 us) (n = 213) (lvls, us = 721, 1074, 1172, 1270, 6189)
[411.437s][info][gc,stats] Pause Init Update Refs (N) = 0.04 s (a = 193 us) (n = 213) (lvls, us = 129, 158, 180, 207, 717)
[411.437s][info][gc,stats] Retire GCLABs = 0.01 s (a = 37 us) (n = 213) (lvls, us = 5, 32, 36, 40, 126)
[411.437s][info][gc,stats] Prepare = 0.02 s (a = 96 us) (n = 213) (lvls, us = 59, 74, 86, 107, 349)
[411.437s][info][gc,stats] Pause Final Update Refs (G) = 0.47 s (a = 2200 us) (n = 213) (lvls, us = 1270, 1699, 1875, 2246, 18276)
[411.437s][info][gc,stats] Pause Final Update Refs (N) = 0.21 s (a = 984 us) (n = 213) (lvls, us = 561, 766, 879, 1016, 3091)
[411.437s][info][gc,stats] Update Roots = 0.16 s (a = 750 us) (n = 213) (lvls, us = 393, 564, 650, 816, 2411)
[411.437s][info][gc,stats] UR: Thread Roots = 0.11 s (a = 497 us) (n = 213) (lvls, us = 150, 400, 463, 535, 1855)
[411.437s][info][gc,stats] Sync Pinned = 0.02 s (a = 75 us) (n = 213) (lvls, us = 36, 60, 68, 82, 246)
[411.437s][info][gc,stats] Trash CSet = 0.00 s (a = 17 us) (n = 213) (lvls, us = 4, 13, 16, 19, 75)
[411.437s][info][gc,stats] Concurrent Reset = 1.87 s (a = 3277 us) (n = 572) (lvls, us = 412, 2910, 3184, 3438, 15269)
[411.437s][info][gc,stats] Concurrent Marking = 122.57 s (a = 214281 us) (n = 572) (lvls, us = 26758, 140625, 212891, 271484, 423661)
[411.437s][info][gc,stats] Concurrent Precleaning = 0.50 s (a = 4234 us) (n = 117) (lvls, us = 191, 3809, 4297, 4980, 7582)
[411.437s][info][gc,stats] Concurrent Roots = 20.79 s (a = 36339 us) (n = 572) (lvls, us = 11328, 29883, 33984, 38477, 138885)
[411.437s][info][gc,stats] Concurrent Evacuation = 22.09 s (a = 38627 us) (n = 572) (lvls, us = 637, 33203, 38477, 44336, 123103)
[411.437s][info][gc,stats] Concurrent Update Refs = 37.84 s (a = 177660 us) (n = 213) (lvls, us = 24414, 132812, 181641, 212891, 631977)
[411.437s][info][gc,stats] Concurrent Cleanup = 0.19 s (a = 247 us) (n = 785) (lvls, us = 79, 180, 219, 264, 1886)
[411.437s][info][gc,stats]
[411.437s][info][gc,stats]
[411.437s][info][gc,stats] Under allocation pressure, concurrent cycles may cancel, and either continue cycle
[411.437s][info][gc,stats] under stop-the-world pause or result in stop-the-world Full GC. Increase heap size,
[411.437s][info][gc,stats] tune GC heuristics, set more aggressive pacing delay, or lower allocation rate
[411.437s][info][gc,stats] to avoid Degenerated and Full GC cycles.
[411.437s][info][gc,stats]
[411.437s][info][gc,stats] 572 successful concurrent GCs
[411.437s][info][gc,stats] 2 invoked explicitly
[411.437s][info][gc,stats] 0 invoked implicitly
[411.437s][info][gc,stats]
[411.437s][info][gc,stats] 0 Degenerated GCs
[411.437s][info][gc,stats] 0 caused by allocation failure
[411.437s][info][gc,stats] 0 upgraded to Full GC
[411.437s][info][gc,stats]
[411.437s][info][gc,stats] 0 Full GCs
[411.437s][info][gc,stats] 0 invoked explicitly
[411.437s][info][gc,stats] 0 invoked implicitly
[411.437s][info][gc,stats] 0 caused by allocation failure
[411.437s][info][gc,stats] 0 upgraded from Degenerated GC
[411.437s][info][gc,stats]
[411.437s][info][gc,stats]
[411.437s][info][gc,stats] ALLOCATION PACING:
[411.437s][info][gc,stats]
[411.437s][info][gc,stats] Max pacing delay is set for 10 ms.
[411.437s][info][gc,stats]
[411.437s][info][gc,stats] Higher delay would prevent application outpacing the GC, but it will hide the GC latencies
[411.437s][info][gc,stats] from the STW pause times. Pacing affects the individual threads, and so it would also be
[411.437s][info][gc,stats] invisible to the usual profiling tools, but would add up to end-to-end application latency.
[411.437s][info][gc,stats] Raise max pacing delay with care.
[411.437s][info][gc,stats]
[411.437s][info][gc,stats] Actual pacing delays histogram:
[411.437s][info][gc,stats]
[411.437s][info][gc,stats] From - To Count Sum
[411.437s][info][gc,stats] 1 ms - 2 ms: 117 58 ms
[411.437s][info][gc,stats] 2 ms - 4 ms: 228 228 ms
[411.437s][info][gc,stats] 4 ms - 8 ms: 993 1986 ms
[411.437s][info][gc,stats] 8 ms - 16 ms: 50477 201908 ms
[411.437s][info][gc,stats] 16 ms - 32 ms: 279 2232 ms
[411.437s][info][gc,stats] 32 ms - 64 ms: 28 448 ms
[411.437s][info][gc,stats] 64 ms - 128 ms: 35 1120 ms
[411.437s][info][gc,stats] 128 ms - 256 ms: 2 128 ms
[411.437s][info][gc,stats] Total: 52159 208108 ms
----------------------------------------------------------
2. Example: class unloading disabled
yields: Pause Final Mark (process weakrefs) 158.299ms
----------------------------------------------------------
java -Xms1G -Xmx1G -XX:+AlwaysPreTouch \
-Xlog:gc,gc+stats \
-XX:+UnlockExperimentalVMOptions \
-XX:+UseShenandoahGC \
-XX:ShenandoahMinFreeThreshold=25 \
-XX:-ClassUnloading \
-jar dacapo-9.12-MR1-bach.jar tradesoap -s large --no-pre-iteration-gc -9 >> $logfile 2>&1
[2.127s][info][gc] Using Shenandoah
Using scaled threading model. 6 processors detected, 6 threads used to drive the workload, in a possible range of [1,512]
...
[297.601s][info][gc] Trigger: Free (255M) is below minimum threshold (255M)
[297.605s][info][gc] GC(450) Concurrent reset 716M->717M(1024M) 3.104ms
[297.608s][info][gc] GC(450) Pause Init Mark (process weakrefs) 2.073ms
[297.771s][info][gc] GC(450) Concurrent marking (process weakrefs) 718M->745M(1024M) 163.327ms
[297.780s][info][gc] GC(450) Concurrent precleaning 745M->746M(1024M) 8.804ms
[297.941s][info][gc] GC(450) Pause Final Mark (process weakrefs) 158.299ms
[297.942s][info][gc] GC(450) Concurrent roots processing 747M->749M(1024M) 0.830ms
[297.942s][info][gc] GC(450) Concurrent cleanup 749M->748M(1024M) 0.171ms
[298.018s][info][gc] GC(450) Concurrent evacuation 748M->797M(1024M) 76.061ms
[298.019s][info][gc] GC(450) Pause Init Update Refs 0.135ms
[298.261s][info][gc] GC(450) Concurrent update references 797M->820M(1024M) 241.528ms
[298.263s][info][gc] GC(450) Pause Final Update Refs 1.334ms
[298.264s][info][gc] GC(450) Concurrent cleanup 820M->328M(1024M) 0.572ms
...
[375.835s][info][gc,stats] Total Pauses (G) = 17.12 s (a = 8827 us) (n = 1939) (lvls, us = 535, 1270, 2695, 7305, 160888)
[375.835s][info][gc,stats] Total Pauses (N) = 14.85 s (a = 7658 us) (n = 1939) (lvls, us = 40, 176, 1641, 6172, 158360)
[375.835s][info][gc,stats] Pause Init Mark (G) = 1.76 s (a = 3054 us) (n = 577) (lvls, us = 2051, 2578, 2852, 3145, 19224)
[375.835s][info][gc,stats] Pause Init Mark (N) = 1.11 s (a = 1916 us) (n = 577) (lvls, us = 1211, 1582, 1777, 2012, 14751)
[375.835s][info][gc,stats] Make Parsable = 0.04 s (a = 70 us) (n = 577) (lvls, us = 23, 49, 59, 81, 424)
[375.835s][info][gc,stats] Clear Liveness = 0.08 s (a = 135 us) (n = 577) (lvls, us = 78, 113, 127, 146, 354)
[375.835s][info][gc,stats] Scan Roots = 0.93 s (a = 1610 us) (n = 577) (lvls, us = 969, 1309, 1484, 1719, 14015)
[375.835s][info][gc,stats] S: Thread Roots = 0.39 s (a = 677 us) (n = 577) (lvls, us = 336, 572, 633, 732, 4006)
[375.835s][info][gc,stats] S: Universe Roots = 0.00 s (a = 5 us) (n = 577) (lvls, us = 2, 4, 4, 5, 142)
[375.835s][info][gc,stats] S: JNI Roots = 0.00 s (a = 1 us) (n = 577) (lvls, us = 1, 1, 1, 1, 7)
[375.835s][info][gc,stats] S: VM Global Roots = 0.00 s (a = 0 us) (n = 577) (lvls, us = 0, 0, 0, 0, 1)
[375.835s][info][gc,stats] S: Synchronizer Roots = 0.00 s (a = 0 us) (n = 577) (lvls, us = 0, 0, 0, 0, 51)
[375.835s][info][gc,stats] S: Management Roots = 0.00 s (a = 7 us) (n = 577) (lvls, us = 2, 3, 3, 4, 1931)
[375.835s][info][gc,stats] S: System Dict Roots = 0.01 s (a = 12 us) (n = 577) (lvls, us = 7, 10, 11, 13, 45)
[375.835s][info][gc,stats] S: CLDG Roots = 0.26 s (a = 448 us) (n = 577) (lvls, us = 156, 344, 447, 506, 2152)
[375.835s][info][gc,stats] S: JVMTI Roots = 0.00 s (a = 1 us) (n = 577) (lvls, us = 0, 1, 1, 1, 28)
[375.835s][info][gc,stats] Resize TLABs = 0.02 s (a = 29 us) (n = 577) (lvls, us = 12, 22, 26, 34, 102)
[375.835s][info][gc,stats] Pause Final Mark (G) = 14.16 s (a = 24547 us) (n = 577) (lvls, us = 4219, 7656, 8906, 11914, 160886)
[375.835s][info][gc,stats] Pause Final Mark (N) = 13.49 s (a = 23375 us) (n = 577) (lvls, us = 3496, 6523, 7852, 10547, 158359)
[375.836s][info][gc,stats] Update Roots = 0.25 s (a = 675 us) (n = 369) (lvls, us = 381, 543, 637, 760, 1911)
[375.836s][info][gc,stats] U: Thread Roots = 0.17 s (a = 473 us) (n = 369) (lvls, us = 326, 389, 447, 535, 935)
[375.836s][info][gc,stats] Finish Queues = 0.23 s (a = 407 us) (n = 577) (lvls, us = 89, 172, 225, 279, 12928)
[375.836s][info][gc,stats] Weak References = 9.13 s (a = 77380 us) (n = 118) (lvls, us = 47, 70898, 78516, 85938, 141317)
[375.836s][info][gc,stats] Process = 9.13 s (a = 77371 us) (n = 118) (lvls, us = 20, 70898, 78516, 85938, 141274)
[375.836s][info][gc,stats] System Purge = 0.19 s (a = 323 us) (n = 577) (lvls, us = 156, 256, 311, 363, 1274)
[375.836s][info][gc,stats] Parallel Cleanup = 0.19 s (a = 322 us) (n = 577) (lvls, us = 156, 254, 309, 363, 1248)
[375.836s][info][gc,stats] Complete Liveness = 0.05 s (a = 88 us) (n = 577) (lvls, us = 41, 65, 79, 98, 966)
[375.836s][info][gc,stats] Retire TLABs = 0.04 s (a = 72 us) (n = 577) (lvls, us = 23, 58, 66, 82, 346)
[375.836s][info][gc,stats] Sync Pinned = 0.02 s (a = 32 us) (n = 577) (lvls, us = 10, 26, 28, 36, 155)
[375.836s][info][gc,stats] Trash CSet = 0.01 s (a = 16 us) (n = 577) (lvls, us = 2, 3, 16, 23, 89)
[375.836s][info][gc,stats] Prepare Evacuation = 0.19 s (a = 325 us) (n = 577) (lvls, us = 127, 268, 312, 365, 1076)
[375.836s][info][gc,stats] Initial Evacuation = 3.31 s (a = 5739 us) (n = 577) (lvls, us = 2539, 4746, 5410, 6348, 16433)
[375.836s][info][gc,stats] E: Thread Roots = 0.28 s (a = 489 us) (n = 577) (lvls, us = 297, 408, 459, 535, 3312)
[375.836s][info][gc,stats] E: Code Cache Roots = 2.23 s (a = 3863 us) (n = 577) (lvls, us = 1152, 3477, 3711, 4102, 10724)
[375.836s][info][gc,stats] E: Universe Roots = 0.00 s (a = 2 us) (n = 577) (lvls, us = 1, 1, 1, 2, 28)
[375.836s][info][gc,stats] E: JVMTI Weak Roots = 0.00 s (a = 0 us) (n = 577) (lvls, us = 0, 0, 0, 0, 2)
[375.836s][info][gc,stats] E: JFR Weak Roots = 0.00 s (a = 0 us) (n = 577) (lvls, us = 0, 0, 0, 0, 17)
[375.836s][info][gc,stats] E: Synchronizer Roots = 0.00 s (a = 1 us) (n = 577) (lvls, us = 0, 0, 0, 0, 18)
[375.836s][info][gc,stats] E: Management Roots = 0.00 s (a = 3 us) (n = 577) (lvls, us = 1, 2, 2, 3, 21)
[375.836s][info][gc,stats] E: System Dict Roots = 0.00 s (a = 8 us) (n = 577) (lvls, us = 5, 6, 6, 7, 50)
[375.836s][info][gc,stats] E: JVMTI Roots = 0.00 s (a = 1 us) (n = 577) (lvls, us = 1, 1, 1, 1, 18)
[375.836s][info][gc,stats] Pause Final Evac (G) = 0.42 s (a = 1137 us) (n = 369) (lvls, us = 695, 967, 1035, 1172, 9748)
[375.836s][info][gc,stats] Pause Final Evac (N) = 0.03 s (a = 82 us) (n = 369) (lvls, us = 40, 70, 76, 89, 209)
[375.836s][info][gc,stats] Retire GCLABs = 0.01 s (a = 35 us) (n = 369) (lvls, us = 16, 29, 33, 37, 137)
[375.836s][info][gc,stats] Pause Init Update Refs (G) = 0.34 s (a = 1628 us) (n = 208) (lvls, us = 490, 1035, 1133, 1250, 77501)
[375.836s][info][gc,stats] Pause Init Update Refs (N) = 0.04 s (a = 178 us) (n = 208) (lvls, us = 84, 152, 166, 195, 742)
[375.836s][info][gc,stats] Retire GCLABs = 0.01 s (a = 33 us) (n = 208) (lvls, us = 10, 28, 33, 36, 118)
[375.836s][info][gc,stats] Prepare = 0.02 s (a = 88 us) (n = 208) (lvls, us = 30, 72, 79, 100, 391)
[375.836s][info][gc,stats] Pause Final Update Refs (G) = 0.43 s (a = 2065 us) (n = 208) (lvls, us = 1250, 1680, 1836, 2031, 11709)
[375.836s][info][gc,stats] Pause Final Update Refs (N) = 0.19 s (a = 892 us) (n = 208) (lvls, us = 604, 723, 822, 926, 3578)
[375.836s][info][gc,stats] Update Roots = 0.14 s (a = 666 us) (n = 208) (lvls, us = 426, 525, 604, 709, 2734)
[375.836s][info][gc,stats] UR: Thread Roots = 0.10 s (a = 466 us) (n = 208) (lvls, us = 312, 387, 434, 492, 1979)
[375.836s][info][gc,stats] Sync Pinned = 0.02 s (a = 76 us) (n = 208) (lvls, us = 33, 60, 67, 79, 779)
[375.836s][info][gc,stats] Trash CSet = 0.00 s (a = 17 us) (n = 208) (lvls, us = 2, 12, 14, 18, 104)
[375.836s][info][gc,stats] Concurrent Reset = 1.75 s (a = 3031 us) (n = 577) (lvls, us = 416, 2715, 2949, 3164, 11012)
[375.836s][info][gc,stats] Concurrent Marking = 124.01 s (a = 214925 us) (n = 577) (lvls, us = 39453, 142578, 210938, 275391, 486606)
[375.836s][info][gc,stats] Concurrent Precleaning = 0.54 s (a = 4552 us) (n = 118) (lvls, us = 240, 4023, 4590, 5098, 8977)
[375.836s][info][gc,stats] Concurrent Roots = 0.96 s (a = 1661 us) (n = 577) (lvls, us = 525, 871, 1055, 1855, 26504)
[375.836s][info][gc,stats] Concurrent Evacuation = 22.68 s (a = 39314 us) (n = 577) (lvls, us = 127, 34375, 38477, 43945, 120119)
[375.836s][info][gc,stats] Concurrent Update Refs = 34.41 s (a = 165418 us) (n = 208) (lvls, us = 21289, 125000, 169922, 199219, 296727)
[375.836s][info][gc,stats] Concurrent Cleanup = 0.18 s (a = 227 us) (n = 785) (lvls, us = 73, 168, 203, 250, 1867)
[375.836s][info][gc,stats]
[375.836s][info][gc,stats]
[375.836s][info][gc,stats] Under allocation pressure, concurrent cycles may cancel, and either continue cycle
[375.836s][info][gc,stats] under stop-the-world pause or result in stop-the-world Full GC. Increase heap size,
[375.836s][info][gc,stats] tune GC heuristics, set more aggressive pacing delay, or lower allocation rate
[375.836s][info][gc,stats] to avoid Degenerated and Full GC cycles.
[375.836s][info][gc,stats]
[375.836s][info][gc,stats] 577 successful concurrent GCs
[375.836s][info][gc,stats] 2 invoked explicitly
[375.836s][info][gc,stats] 0 invoked implicitly
[375.836s][info][gc,stats]
[375.836s][info][gc,stats] 0 Degenerated GCs
[375.836s][info][gc,stats] 0 caused by allocation failure
[375.836s][info][gc,stats] 0 upgraded to Full GC
[375.836s][info][gc,stats]
[375.836s][info][gc,stats] 0 Full GCs
[375.836s][info][gc,stats] 0 invoked explicitly
[375.836s][info][gc,stats] 0 invoked implicitly
[375.836s][info][gc,stats] 0 caused by allocation failure
[375.836s][info][gc,stats] 0 upgraded from Degenerated GC
[375.836s][info][gc,stats]
[375.836s][info][gc,stats]
[375.836s][info][gc,stats] ALLOCATION PACING:
[375.836s][info][gc,stats]
[375.836s][info][gc,stats] Max pacing delay is set for 10 ms.
[375.836s][info][gc,stats]
[375.836s][info][gc,stats] Higher delay would prevent application outpacing the GC, but it will hide the GC latencies
[375.836s][info][gc,stats] from the STW pause times. Pacing affects the individual threads, and so it would also be
[375.836s][info][gc,stats] invisible to the usual profiling tools, but would add up to end-to-end application latency.
[375.836s][info][gc,stats] Raise max pacing delay with care.
[375.836s][info][gc,stats]
[375.836s][info][gc,stats] Actual pacing delays histogram:
[375.836s][info][gc,stats]
[375.836s][info][gc,stats] From - To Count Sum
[375.836s][info][gc,stats] 1 ms - 2 ms: 257 128 ms
[375.836s][info][gc,stats] 2 ms - 4 ms: 201 201 ms
[375.836s][info][gc,stats] 4 ms - 8 ms: 364 728 ms
[375.836s][info][gc,stats] 8 ms - 16 ms: 52317 209268 ms
[375.837s][info][gc,stats] 16 ms - 32 ms: 908 7264 ms
[375.837s][info][gc,stats] 32 ms - 64 ms: 13 208 ms
[375.837s][info][gc,stats] 64 ms - 128 ms: 30 960 ms
[375.837s][info][gc,stats] Total: 54090 218757 ms
More information about the shenandoah-dev
mailing list