0

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.

Eugene
  • 117,005
  • 15
  • 201
  • 306
  • IMHO you are comparing apples and oranges: the "0:00.57elapsed" is the time that the `jcmd` command was running. But the jcmd command is a separate process from your application, it's run time is inherently longer than the time needed for a full GC: a new Java process must be created, the classes for jcmd be loaded, it must connect to the target JVM, the target JVM runs the full GC, the Java process for jcmd is terminated. – Thomas Kläger Apr 04 '23 at 05:38
  • @ThomasKläger very much agreed on your point, I am inclined to treat those "tens of seconds" I see under load when running `jcmd` as the overhead of the `jcmd` itself. – Eugene Apr 04 '23 at 06:00

0 Answers0