Hi guys, Need GC expert to help me understand a strange G1GC behavior here, it has been causing trouble for us for a while, and I've spent more than a week investigating into this without fully addressing it. Really appreciate if I can get some help here.
Our code is running on OpenJDK 11 with following GC settings:
-Xms144179m -Xmx144179m -XX:+AlwaysPreTouch -XX:+UseG1GC
> -XX:MaxGCPauseMillis=500 -Xlog:gc*=debug:file=/tmp/zeus.gc.log
And it's running on machine with 256GB memory and 80 processors.
There are long GC pause (> 2s) from time to time during young GC, and most
of the time is spent in "Evacuating Collection Set". By enabling the GC
debug log, found most of the time was spent in "Object Copy" phase:
...
[74835.843s][debug ][gc,phases ] GC(43) Object Copy (ms):
Min: 2271.3, Avg: 2287.8, Max: 2401.6, Diff: 130.2, Sum: 86935.4,
Workers: 38
[74835.843s][debug ][gc,phases ] GC(43) Termination (ms):
Min: 3.7, Avg: 4.2, Max: 5.0, Diff: 1.3, Sum: 160.7, Workers: 38
[74835.843s][debug ][gc,phases ] GC(43) Termination
Attempts: Min: 3523, Avg: 3654.5, Max: 3782, Diff: 259, Sum: 138872,
Workers: 38
...
[74835.843s][info ][gc,heap ] GC(43) Eden regions:
1261->0(1258)
[74835.843s][info ][gc,heap ] GC(43) Survivor regions:
90->93(169)
[74835.843s][info ][gc,heap ] GC(43) Old regions: 266->266
[74835.843s][info ][gc,heap ] GC(43) Humongous regions:
7->7
[74835.843s][info ][gc,metaspace ] GC(43) Metaspace:
46892K->46892K(49152K)
[74835.843s][debug ][gc,heap ] GC(43) Heap after GC
invocations=44 (full 0): garbage-first heap total 147652608K, used
11987833K [0x00007f0c34000000, 0x00007f2f68000000)
[74835.843s][debug ][gc,heap ] GC(43) region size 32768K, 93
young (3047424K), 93 survivors (3047424K)
[74835.843s][debug ][gc,heap ] GC(43) Metaspace used
46892K, capacity 47403K, committed 47712K, reserved 49152K
[74835.843s][info ][gc ] GC(43) Pause Young
(Normal) (G1 Evacuation Pause) 51966M->11706M(144192M) 2439.941ms
[74835.843s][info ][gc,cpu ] GC(43) User=14.54s Sys=1.86s
Real=2.44s
Looked into the JDK docs and other blogs shared online to understand the
G1GC, tried various settings like reducing the minimal young gen size
-XX:G1NewSizePercent=1, -XX:ParallelGCThreads=64 and PLAB size, etc, and
they didn't address the issue.
There are blogs mentioned things like memory swap or disk IO might causing
long Object Copy, but there are plentiful of memory in the system, and we
didn't see swap kick in from atop.
Since I cannot get the answer online, I tried to read the code and add
instrument logs to understand the GC behavior (you can find the changed
code in the attachment), and found that the time is spent in long time
stealing works from other task queues, the full log is attached.
There is no single GC thread got caught in root scanning or CPU starving,
all of them finished the trim_queue within a few ms. And, started to the
long steal_and_trim_queue loop. In
G1ParScanThreadState::do_oop_partial_array, it deals with array specially,
which will only scan a subset of object array and push remainder back if
array is bigger than ParGCArrayScanChunk, and we do have array object
(temporary) larger than 500k sometimes. I thought this might be the issue,
but we still see the long stealing behavior even raised this value from 50
to 500, and we saw there are cases there is no large array but still had
this problem.
By adding more logs, saw all the GC threads seemed to steal the same task
and then stole by another, the task should be different, but the behavior
seems weird:
[24632.803s][debug ][gc,ergo ] GC(11) worker 1 stealed from
queue 32, its size was 1
[24632.803s][debug ][gc,ergo ] GC(11) worker 28 stealed from
queue 1, its size was 2
[24632.803s][debug ][gc,ergo ] GC(11) worker 24 stealed from
queue 28, its size was 1
[24632.803s][debug ][gc,ergo ] GC(11) worker 4 stealed from
queue 24, its size was 1
[24632.804s][debug ][gc,ergo ] GC(11) worker 5 stealed from
queue 4, its size was 1
[24632.804s][debug ][gc,ergo ] GC(11) worker 15 stealed from
queue 5, its size was 1
[24632.804s][debug ][gc,ergo ] GC(11) worker 37 stealed from
queue 15, its size was 1
[24632.804s][debug ][gc,ergo ] GC(11) worker 16 stealed from
queue 37, its size was 1
[24632.804s][debug ][gc,ergo ] GC(11) worker 7 stealed from
queue 16, its size was 1
[24632.804s][debug ][gc,ergo ] GC(11) worker 2 stealed from
queue 7, its size was 1
[24632.804s][debug ][gc,ergo ] GC(11) worker 29 stealed from
queue 2, its size was 1
[24632.804s][debug ][gc,ergo ] GC(11) worker 15 stealed from
queue 29, its size was 1
I tried to follow the code more, and found G1ScanEvacuatedObjClosure might
try to push obj into the task queue after copying the obj to survivor
space, but I'm not able to follow and think of why this could keep
happening for a few thousands of stealing, please give me some insights why
this happened, any known scenarios could trigger this?
One thing I'm trying is cap the steal behavior, skip steal if the task
queue has less than 5 tasks, this might reduce the contention and CPU cost
due to busy steal from those GC threads, but I'm not sure if this could
fully address the issue here, I'll update here based on the testing.
Thanks again for taking your time to go through these, really appreciate
any help here!
Thanks,
Fangmin
gc.log.gz
Description: GNU Zip compressed data
instrumented_g1gc.diff
Description: Binary data
_______________________________________________ hotspot-gc-use mailing list hotspot-gc-use@openjdk.java.net https://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use
