现象

应用的YGC耗时非常长

GC日志

发生问题的GC日志片段

{Heap before GC invocations=309687 (full 0):
garbage-first heap total 3072000K, used 2336226K [0x00000006e6800000, 0x00000006e7000bb8, 0x00000007e0800000)
region size 8192K, 225 young (1843200K), 3 survivors (24576K)
Metaspace used 162720K, capacity 168480K, committed 169600K, reserved 1198080K
class space used 19617K, capacity 20637K, committed 20864K, reserved 1048576K
2023-08-16T13:46:22.300+0800: 4126158.273: [GC pause (G1 Evacuation Pause) (young) 4126158.273: [G1Ergonomics (CSet Construction) start choosing CSet, _pending_cards: 7000, predicted base time: 87.03 ms, remaining time: 62.97 ms, target pause time: 150.00 ms]
4126158.273: [G1Ergonomics (CSet Construction) add young regions to CSet, eden: 222 regions, survivors: 3 regions, predicted young region time: 5.37 ms]
4126158.273: [G1Ergonomics (CSet Construction) finish choosing CSet, eden: 222 regions, survivors: 3 regions, old: 0 regions, predicted pause time: 92.40 ms, target pause time: 150.00 ms]
2023-08-16T13:46:22.313+0800: 4126158.285: [SoftReference, 0 refs, 4.4632850 secs]2023-08-16T13:46:26.776+0800: 4126162.749: [WeakReference, 4 refs, 0.0000152 secs]2023-08-16T13:46:26.776+0800: 4126162.749: [FinalReference, 14 refs, 0.0000233 secs]2023-08-16T13:46:26.777+0800: 4126162.749: [PhantomReference, 0 refs, 0 refs, 0.0000047 secs]2023-08-16T13:46:26.777+0800: 4126162.749: [JNI Weak Reference, 0.1101531 secs], 4.5877433 secs]
[Parallel Time: 12.5 ms, GC Workers: 4]
[GC Worker Start (ms): Min: 4126158272.8, Avg: 4126158272.9, Max: 4126158272.9, Diff: 0.0]
[Ext Root Scanning (ms): Min: 2.3, Avg: 2.6, Max: 2.8, Diff: 0.5, Sum: 10.2]
[Update RS (ms): Min: 2.0, Avg: 2.0, Max: 2.1, Diff: 0.1, Sum: 8.2]
[Processed Buffers: Min: 59, Avg: 63.5, Max: 66, Diff: 7, Sum: 254]
[Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
[Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Object Copy (ms): Min: 7.5, Avg: 7.7, Max: 8.0, Diff: 0.4, Sum: 31.0]
[Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Termination Attempts: Min: 1, Avg: 2.0, Max: 4, Diff: 3, Sum: 8]
[GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
[GC Worker Total (ms): Min: 12.4, Avg: 12.4, Max: 12.4, Diff: 0.0, Sum: 49.6]
[GC Worker End (ms): Min: 4126158285.2, Avg: 4126158285.2, Max: 4126158285.3, Diff: 0.0]
[Code Root Fixup: 0.0 ms]
[Code Root Purge: 0.0 ms]
[Clear CT: 0.8 ms]
[Other: 4574.4 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 4573.6 ms]
[Ref Enq: 0.0 ms]
[Redirty Cards: 0.1 ms]
[Humongous Register: 0.0 ms]
[Humongous Reclaim: 0.0 ms]
[Free CSet: 0.2 ms]
[Eden: 1776.0M(1776.0M)->0.0B(104.0M) Survivors: 24.0M->40.0M Heap: 2281.5M(3000.0M)->518.4M(3000.0M)]
Heap after GC invocations=309688 (full 0):
garbage-first heap total 3072000K, used 530815K [0x00000006e6800000, 0x00000006e7000bb8, 0x00000007e0800000)
region size 8192K, 5 young (40960K), 5 survivors (40960K)
Metaspace used 162720K, capacity 168480K, committed 169600K, reserved 1198080K
class space used 19617K, capacity 20637K, committed 20864K, reserved 1048576K
}
[Times: user=0.13 sys=0.03, real=4.59 secs]

发生问题之前
{Heap before GC invocations=309686 (full 0):
garbage-first heap total 3072000K, used 2335059K [0x00000006e6800000, 0x00000006e7000bb8, 0x00000007e0800000)
region size 8192K, 225 young (1843200K), 2 survivors (16384K)
Metaspace used 162720K, capacity 168480K, committed 169600K, reserved 1198080K
class space used 19617K, capacity 20637K, committed 20864K, reserved 1048576K
2023-08-16T13:46:13.744+0800: 4126149.716: [GC pause (G1 Evacuation Pause) (young) 4126149.716: [G1Ergonomics (CSet Construction) start choosing CSet, _pending_cards: 6732, predicted base time: 87.81 ms, remaining time: 62.19 ms, target pause time: 150.00 ms]
4126149.716: [G1Ergonomics (CSet Construction) add young regions to CSet, eden: 223 regions, survivors: 2 regions, predicted young region time: 5.48 ms]
4126149.716: [G1Ergonomics (CSet Construction) finish choosing CSet, eden: 223 regions, survivors: 2 regions, old: 0 regions, predicted pause time: 93.29 ms, target pause time: 150.00 ms]
2023-08-16T13:46:13.756+0800: 4126149.728: [SoftReference, 0 refs, 0.0000687 secs]2023-08-16T13:46:13.756+0800: 4126149.728: [WeakReference, 3 refs, 0.0000063 secs]2023-08-16T13:46:13.756+0800: 4126149.728: [FinalReference, 20 refs, 0.0000226 secs]2023-08-16T13:46:13.756+0800: 4126149.728: [PhantomReference, 0 refs, 0 refs, 0.0000045 secs]2023-08-16T13:46:13.756+0800: 4126149.728: [JNI Weak Reference, 0.0784874 secs], 0.0915210 secs]
[Parallel Time: 11.9 ms, GC Workers: 4]
[GC Worker Start (ms): Min: 4126149716.2, Avg: 4126149716.3, Max: 4126149716.3, Diff: 0.1]
[Ext Root Scanning (ms): Min: 2.3, Avg: 2.5, Max: 2.8, Diff: 0.5, Sum: 10.1]
[Update RS (ms): Min: 2.1, Avg: 2.1, Max: 2.2, Diff: 0.1, Sum: 8.5]
[Processed Buffers: Min: 59, Avg: 66.2, Max: 74, Diff: 15, Sum: 265]
[Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.2]
[Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Object Copy (ms): Min: 7.0, Avg: 7.1, Max: 7.3, Diff: 0.3, Sum: 28.5]
[Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 4]
[GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.2]
[GC Worker Total (ms): Min: 11.8, Avg: 11.9, Max: 11.9, Diff: 0.1, Sum: 47.5]
[GC Worker End (ms): Min: 4126149728.1, Avg: 4126149728.1, Max: 4126149728.1, Diff: 0.0]
[Code Root Fixup: 0.0 ms]
[Code Root Purge: 0.0 ms]
[Clear CT: 0.2 ms]
[Other: 79.4 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 78.7 ms]
[Ref Enq: 0.0 ms]
[Redirty Cards: 0.1 ms]
[Humongous Register: 0.0 ms]
[Humongous Reclaim: 0.0 ms]
[Free CSet: 0.2 ms]
[Eden: 1784.0M(1784.0M)->0.0B(1776.0M) Survivors: 16.0M->24.0M Heap: 2280.3M(3000.0M)->505.5M(3000.0M)]
Heap after GC invocations=309687 (full 0):
garbage-first heap total 3072000K, used 517602K [0x00000006e6800000, 0x00000006e7000bb8, 0x00000007e0800000)
region size 8192K, 3 young (24576K), 3 survivors (24576K)
Metaspace used 162720K, capacity 168480K, committed 169600K, reserved 1198080K
class space used 19617K, capacity 20637K, committed 20864K, reserved 1048576K
}
[Times: user=0.10 sys=0.02, real=0.09 secs]

GC参数

-XX:+UnlockExperimentalVMOptions
-XX:+G1TraceEagerReclaimHumongousObjects
-Xmx4000m
-Xms3000m
-XX:+UseG1GC
-XX:MaxGCPauseMillis=150
-XX:G1HeapRegionSize=8M
-XX:InitiatingHeapOccupancyPercent=25
-XX:+PrintCommandLineFlags
-XX:+PrintGCDetails
-XX:+PrintGCTimeStamps
-XX:+PrintGCDateStamps
-XX:MetaspaceSize=256m
-XX:MaxMetaspaceSize=512m
-XX:+HeapDumpOnOutOfMemoryError
-Xloggc:logs/gc-%t.log
-XX:+UseGCLogFileRotation
-XX:NumberOfGCLogFiles=16
-XX:GCLogFileSize=128M
-XX:+PrintGCApplicationStoppedTime
-XX:+PrintAdaptiveSizePolicy
-XX:+PrintHeapAtGC
-XX:+PrintReferenceGC

怀疑点

[Ref Proc: 4573.6 ms]，此处耗时四秒，查看前面的明细，发现[SoftReference, 0 refs, 4.4632850 secs]，但refs为0，非常奇怪。

另外则是[JNI Weak Reference, 0.1101531 secs]JNI的引用处理也比较耗时。