I am triggering a gc cycle in shenandoah using jcmd:
time ./jcmd 1637 GC.run
1637:
Command executed successfully
0.49user 0.07system 0:00.57elapsed 98%CPU (0avgtext+0avgdata 47384maxresident)k
0inputs+64outputs (0major+11292minor)pagefaults 0swaps
I guess the thing I care about is : 0:00.57elapsed. Now if I look at the gc.logs:
[5047.153s][info][gc] Trigger: Explicit GC request (Diagnostic Command)
[5047.154s][info][gc] GC(22) Concurrent reset 1.321ms
[5047.156s][info][gc] GC(22) Pause Init Mark (process weakrefs) (unload classes) 1.683ms
[5047.231s][info][gc] GC(22) Concurrent marking (process weakrefs) (unload classes) 74.894ms
[5047.232s][info][gc] GC(22) Concurrent precleaning 0.769ms
[5047.430s][info][gc] GC(22) Pause Final Mark (process weakrefs) (unload classes) 197.860ms
[5047.431s][info][gc] GC(22) Concurrent cleanup 1160M->744M(28672M) 0.137ms
[5047.434s][info][gc] GC(22) Concurrent evacuation 3.419ms
[5047.435s][info][gc] GC(22) Pause Init Update Refs 0.037ms
[5047.471s][info][gc] GC(22) Concurrent update references 36.412ms
[5047.472s][info][gc] GC(22) Pause Final Update Refs 0.411ms
[5047.472s][info][gc] GC(22) Concurrent cleanup 768M->232M(28672M) 0.071ms
I see 4 Pauses, sum them up:
1.683 + 197.860 + 0.037 + 0.411
I get around 200ms, which is very different than the elapsed time.
On the other hand, if I take when the cycle ended: 5047.472 and when it started: 5047.153, I get yet another different value of 319ms.
So who is correct here? Just in case, the system is:
java -version
openjdk version "11.0.15" 2022-04-19 LTS
and uname -a:
3.10.0-1160.66.1.el7.x86_64.
The reason I am asking is that sometimes, under heavy load, if I run the same jcmd <PID> GC.run, it is stuck for tens of seconds, but when I look at the logs, the majority of time is eaten by Concurrent marking (process weakrefs) (unload classes), which is supposed to be fully concurrent.
In essence, I would like to know for how much time was the app stopped during a GC cycle (excluding safepoints, we track that too).
Thank you.