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:
e 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!
...
[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
_______________________________________________
hotspot-gc-use mailing list
hotspot-gc-use@openjdk.java.net
https://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use
