性能问答>G1 Ref Proc耗时增加,Eden区变小导致ygc增多>
2回复
2年前

G1 Ref Proc耗时增加,Eden区变小导致ygc增多



待检查的参数

java
-server
-Dfile.encoding=UTF-8
-Dsun.jnu.encoding=UTF-8
-Djava.io.tmpdir=/tmp
-Djava.net.preferIPv6Addresses=false
-Xmx12g
-Xms12g
-XX:G1HeapRegionSize=4M
-XX:ParallelGCThreads=10
-XX:MetaspaceSize=256m
-XX:MaxMetaspaceSize=256m
-XX:+HeapDumpOnOutOfMemoryError
-XX:ReservedCodeCacheSize=128m
-XX:InitialCodeCacheSize=128m
-XX:+UseG1GC
-XX:MaxGCPauseMillis=30
-XX:+PrintGCDetails
-XX:+PrintHeapAtGC
-XX:+PrintTenuringDistribution
-XX:+PrintGCTimeStamps
-XX:+PrintGCDateStamps
-XX:InitiatingHeapOccupancyPercent=50
-XX:MaxTenuringThreshold=7
-XX:+PrintAdaptiveSizePolicy
-XX:+PrintReferenceGC

最近发现线上有服务器偶尔ygc次数突增,看了下gc日志,发现由于eden区满了导致,而eden区非常小,然后在看前一次ygc,发现Ref Proc耗时增加,gc之后eden区就变小了,下面是gc日志,求大佬帮忙分析一下原因

2019-11-21T17:58:15.039+0800: 9652.917: [GC pause (G1 Evacuation Pause) (young)
Desired survivor size 425721856 bytes, new threshold 7 (max 7)
- age   1:   26659168 bytes,   26659168 total
- age   2:      83200 bytes,   26742368 total
- age   3:      23608 bytes,   26765976 total
- age   4:      62368 bytes,   26828344 total
- age   5:      13024 bytes,   26841368 total
- age   6:      21808 bytes,   26863176 total
- age   7:     108544 bytes,   26971720 total
 9652.917: [G1Ergonomics (CSet Construction) start choosing CSet, _pending_cards: 24440, predicted base time: 8.60 ms, remaining time: 21.40 ms, target pause time: 30.00 ms]
 9652.917: [G1Ergonomics (CSet Construction) add young regions to CSet, eden: 1612 regions, survivors: 10 regions, predicted young region time: 21.84 ms]
 9652.917: [G1Ergonomics (CSet Construction) finish choosing CSet, eden: 1612 regions, survivors: 10 regions, old: 0 regions, predicted pause time: 30.44 ms, target pause time: 30.00 ms]
9652.931: [SoftReference, 0 refs, 0.4740073 secs]9653.405: [WeakReference, 98 refs, 0.0000467 secs]9653.405: [FinalReference, 48 refs, 0.0000506 secs]9653.405: [PhantomReference, 0 refs, 7 refs, 0.0000100 secs]9653.405: [JNI Weak Reference, 0.0002777 secs], 0.4933979 secs]
   [Parallel Time: 13.2 ms, GC Workers: 10]
      [GC Worker Start (ms): Min: 9652917.4, Avg: 9652917.5, Max: 9652917.6, Diff: 0.2]
      [Ext Root Scanning (ms): Min: 1.7, Avg: 1.9, Max: 2.5, Diff: 0.8, Sum: 19.4]
      [Update RS (ms): Min: 2.5, Avg: 2.9, Max: 3.1, Diff: 0.6, Sum: 29.2]
         [Processed Buffers: Min: 16, Avg: 40.1, Max: 62, Diff: 46, Sum: 401]
      [Scan RS (ms): Min: 0.4, Avg: 0.5, Max: 0.6, Diff: 0.2, Sum: 5.0]
      [Code Root Scanning (ms): Min: 0.1, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.8]
      [Object Copy (ms): Min: 7.1, Avg: 7.3, Max: 7.3, Diff: 0.2, Sum: 72.6]
      [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 1.1]
      [GC Worker Total (ms): Min: 12.7, Avg: 12.8, Max: 13.0, Diff: 0.3, Sum: 128.1]
      [GC Worker End (ms): Min: 9652930.2, Avg: 9652930.3, Max: 9652930.4, Diff: 0.2]
   [Code Root Fixup: 0.3 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.9 ms]
   [Other: 479.0 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 474.8 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.4 ms]
      [Humongous Reclaim: 0.1 ms]
      [Free CSet: 2.4 ms]
   [Eden: 6448.0M(6448.0M)->0.0B(576.0M) Survivors: 40.0M->36.0M Heap: 6700.9M(12.0G)->226.0M(12.0G)]
Heap after GC invocations=259 (full 0):
 garbage-first heap   total 12582912K, used 231394K [0x00000004c0000000, 0x00000004c0406000, 0x00000007c0000000)
  region size 4096K, 9 young (36864K), 9 survivors (36864K)
 Metaspace       used 117417K, capacity 120762K, committed 121088K, reserved 1157120K
  class space    used 12546K, capacity 13190K, committed 13312K, reserved 1048576K
}
 [Times: user=0.14 sys=0.00, real=0.50 secs]
{Heap before GC invocations=259 (full 0):
 garbage-first heap   total 12582912K, used 821218K [0x00000004c0000000, 0x00000004c0406000, 0x00000007c0000000)
  region size 4096K, 153 young (626688K), 9 survivors (36864K)
 Metaspace       used 117420K, capacity 120762K, committed 121088K, reserved 1157120K
  class space    used 12546K, capacity 13190K, committed 13312K, reserved 1048576K
2019-11-21T17:58:17.588+0800: 9655.465: [GC pause (G1 Evacuation Pause) (young)
Desired survivor size 41943040 bytes, new threshold 7 (max 7)
- age   1:   20585760 bytes,   20585760 total
- age   2:     270688 bytes,   20856448 total
- age   3:      66696 bytes,   20923144 total
- age   4:      20184 bytes,   20943328 total
- age   5:      55384 bytes,   20998712 total
- age   6:      12080 bytes,   21010792 total
- age   7:      21760 bytes,   21032552 total
 9655.465: [G1Ergonomics (CSet Construction) start choosing CSet, _pending_cards: 4337, predicted base time: 239.24 ms, remaining time: 0.00 ms, target pause time: 30.00 ms]
 9655.465: [G1Ergonomics (CSet Construction) add young regions to CSet, eden: 144 regions, survivors: 9 regions, predicted young region time: 6.65 ms]
 9655.465: [G1Ergonomics (CSet Construction) finish choosing CSet, eden: 144 regions, survivors: 9 regions, old: 0 regions, predicted pause time: 245.88 ms, target pause time: 30.00 ms]
9655.475: [SoftReference, 0 refs, 0.0000451 secs]9655.475: [WeakReference, 116 refs, 0.0000292 secs]9655.475: [FinalReference, 32 refs, 0.0000190 secs]9655.475: [PhantomReference, 0 refs, 7 refs, 0.0000062 secs]9655.475: [JNI Weak Reference, 0.0002180 secs], 0.0127548 secs]
   [Parallel Time: 9.3 ms, GC Workers: 10]
      [GC Worker Start (ms): Min: 9655465.4, Avg: 9655465.5, Max: 9655465.6, Diff: 0.2]
      [Ext Root Scanning (ms): Min: 1.7, Avg: 1.9, Max: 2.4, Diff: 0.7, Sum: 18.9]
      [Update RS (ms): Min: 0.5, Avg: 1.0, Max: 1.3, Diff: 0.8, Sum: 9.7]
         [Processed Buffers: Min: 1, Avg: 30.9, Max: 58, Diff: 57, Sum: 309]
      [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.0, Sum: 0.4]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [Object Copy (ms): Min: 5.9, Avg: 6.0, Max: 6.1, Diff: 0.2, Sum: 60.5]
      [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.3]
      [GC Worker Total (ms): Min: 8.9, Avg: 9.0, Max: 9.1, Diff: 0.2, Sum: 89.8]
      [GC Worker End (ms): Min: 9655474.5, Avg: 9655474.5, Max: 9655474.5, Diff: 0.0]
   [Code Root Fixup: 0.3 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.3 ms]
   [Other: 2.8 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.7 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.3 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.4 ms]
   [Eden: 576.0M(576.0M)->0.0B(564.0M) Survivors: 36.0M->48.0M Heap: 802.0M(12.0G)->238.8M(12.0G)]
Heap after GC invocations=260 (full 0):
 garbage-first heap   total 12582912K, used 244497K [0x00000004c0000000, 0x00000004c0406000, 0x00000007c0000000)
  region size 4096K, 12 young (49152K), 12 survivors (49152K)
 Metaspace       used 117420K, capacity 120762K, committed 121088K, reserved 1157120K
  class space    used 12546K, capacity 13190K, committed 13312K, reserved 1048576K
}
 [Times: user=0.09 sys=0.00, real=0.02 secs]
{Heap before GC invocations=260 (full 0):
 garbage-first heap   total 12582912K, used 822033K [0x00000004c0000000, 0x00000004c0406000, 0x00000007c0000000)
  region size 4096K, 153 young (626688K), 12 survivors (49152K)
 Metaspace       used 117420K, capacity 120762K, committed 121088K, reserved 1157120K
  class space    used 12546K, capacity 13190K, committed 13312K, reserved 1048576K
2019-11-21T17:58:20.105+0800: 9657.983: [GC pause (G1 Evacuation Pause) (young)
Desired survivor size 41943040 bytes, new threshold 7 (max 7)
- age   1:   10102336 bytes,   10102336 total
- age   2:   18236752 bytes,   28339088 total
- age   3:     258520 bytes,   28597608 total
- age   4:      62824 bytes,   28660432 total
- age   5:      20128 bytes,   28680560 total
- age   6:      55384 bytes,   28735944 total
- age   7:      12080 bytes,   28748024 total
 9657.983: [G1Ergonomics (CSet Construction) start choosing CSet, _pending_cards: 4155, predicted base time: 186.50 ms, remaining time: 0.00 ms, target pause time: 30.00 ms]
 9657.983: [G1Ergonomics (CSet Construction) add young regions to CSet, eden: 141 regions, survivors: 12 regions, predicted young region time: 9.32 ms]
 9657.983: [G1Ergonomics (CSet Construction) finish choosing CSet, eden: 141 regions, survivors: 12 regions, old: 0 regions, predicted pause time: 195.82 ms, target pause time: 30.00 ms]
9657.994: [SoftReference, 0 refs, 0.0000472 secs]9657.994: [WeakReference, 122 refs, 0.0000282 secs]9657.994: [FinalReference, 23 refs, 0.0000081 secs]9657.994: [PhantomReference, 0 refs, 7 refs, 0.0000061 secs]9657.994: [JNI Weak Reference, 0.0002269 secs], 0.0131984 secs]
   [Parallel Time: 9.9 ms, GC Workers: 10]
      [GC Worker Start (ms): Min: 9657983.5, Avg: 9657983.6, Max: 9657983.7, Diff: 0.2]
      [Ext Root Scanning (ms): Min: 1.3, Avg: 1.5, Max: 2.2, Diff: 1.0, Sum: 15.1]
      [Update RS (ms): Min: 0.2, Avg: 0.8, Max: 1.3, Diff: 1.1, Sum: 8.3]
         [Processed Buffers: Min: 1, Avg: 28.2, Max: 58, Diff: 57, Sum: 282]
      [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.4]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [Object Copy (ms): Min: 6.9, Avg: 7.1, Max: 7.2, Diff: 0.3, Sum: 71.5]
      [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.6]
      [GC Worker Total (ms): Min: 9.5, Avg: 9.6, Max: 9.7, Diff: 0.2, Sum: 96.0]
      [GC Worker End (ms): Min: 9657993.1, Avg: 9657993.2, Max: 9657993.3, Diff: 0.1]
   [Code Root Fixup: 0.1 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.3 ms]
   [Other: 2.9 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.6 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.3 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.3 ms]
   [Eden: 564.0M(564.0M)->0.0B(576.0M) Survivors: 48.0M->36.0M Heap: 802.8M(12.0G)->228.0M(12.0G)]
Heap after GC invocations=261 (full 0):
 garbage-first heap   total 12582912K, used 233503K [0x00000004c0000000, 0x00000004c0406000, 0x00000007c0000000)
  region size 4096K, 9 young (36864K), 9 survivors (36864K)
 Metaspace       used 117420K, capacity 120762K, committed 121088K, reserved 1157120K
  class space    used 12546K, capacity 13190K, committed 13312K, reserved 1048576K
}
 [Times: user=0.10 sys=0.01, real=0.01 secs]
{Heap before GC invocations=261 (full 0):
 garbage-first heap   total 12582912K, used 828515K [0x00000004c0000000, 0x00000004c0406000, 0x00000007c0000000)
  region size 4096K, 153 young (626688K), 9 survivors (36864K)
 Metaspace       used 117420K, capacity 120762K, committed 121088K, reserved 1157120K
  class space    used 12546K, capacity 13190K, committed 13312K, reserved 1048576K
5573 阅读
请先登录,再评论

主要是处理SoftRef的时候耗时,因为这些SoftRef都没有达到要回收的阶段,可能这种SoftRef还不少,这个可以结合你的代码来看,是否有很多SoftRef对象创建,可以通过加上-XX:SoftRefLRUPolicyMSPerMB=0看看,不过设置这个之后SoftRef相当于失效了,还是建议找出SoftRef创建的地方

2年前

jdk版本 1.8.0_45

2年前