性能问答>4C8G G1 YGC时间过长求助>
10回复

4C8G G1 YGC时间过长求助



待检查的参数

-Dsun.misc.URLClassPath.disableJarChecking=true
-server
-Xmx4096M
-Xms4096M
-XX:MaxMetaspaceSize=512M
-XX:MetaspaceSize=512M
-XX:MaxDirectMemorySize=512M
-XX:+UseG1GC
-XX:MaxGCPauseMillis=100
-XX:+ParallelRefProcEnabled
-XX:ErrorFile=logs/hs_err_pid%p.log
-Xloggc:logs/gc.log
-XX:HeapDumpPath=logs
-XX:+PrintGCDetails
-XX:+PrintGCDateStamps
-XX:+HeapDumpOnOutOfMemoryError

服务规格:4C 8G
操作系统:Linux
Java version: 1.8.0_18
CPU 使用率:不超过15%

GC部分日志如下

2019-10-31T07:35:58.384+0000: 89696.085: [GC pause (G1 Evacuation Pause) (young), 0.0711148 secs]
   [Parallel Time: 66.6 ms, GC Workers: 4]
      [GC Worker Start (ms): Min: 89696085.9, Avg: 89696085.9, Max: 89696085.9, Diff: 0.0]
      [Ext Root Scanning (ms): Min: 3.1, Avg: 3.3, Max: 3.6, Diff: 0.5, Sum: 13.3]
      [Update RS (ms): Min: 11.7, Avg: 11.9, Max: 12.3, Diff: 0.6, Sum: 47.7]
         [Processed Buffers: Min: 54, Avg: 59.0, Max: 65, Diff: 11, Sum: 236]
      [Scan RS (ms): Min: 15.9, Avg: 16.3, Max: 16.5, Diff: 0.6, Sum: 65.3]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [Object Copy (ms): Min: 34.6, Avg: 34.8, Max: 35.0, Diff: 0.5, Sum: 139.1]
      [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
         [Termination Attempts: Min: 1, Avg: 37.5, Max: 72, Diff: 71, Sum: 150]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.3]
      [GC Worker Total (ms): Min: 66.4, Avg: 66.4, Max: 66.5, Diff: 0.1, Sum: 265.7]
      [GC Worker End (ms): Min: 89696152.3, Avg: 89696152.3, Max: 89696152.4, Diff: 0.1]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.5 ms]
   [Other: 4.0 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 1.5 ms]
      [Ref Enq: 0.1 ms]
      [Redirty Cards: 0.2 ms]
      [Humongous Register: 0.1 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 1.4 ms]
   [Eden: 2426.0M(2426.0M)->0.0B(2426.0M) Survivors: 30.0M->30.0M Heap: 3588.5M(4096.0M)->1164.1M(4096.0M)]
 [Times: user=0.27 sys=0.00, real=0.07 secs]
2019-10-31T07:36:07.777+0000: 89705.478: [GC pause (G1 Evacuation Pause) (young), 0.0704454 secs]
   [Parallel Time: 65.6 ms, GC Workers: 4]
      [GC Worker Start (ms): Min: 89705478.1, Avg: 89705478.1, Max: 89705478.1, Diff: 0.0]
      [Ext Root Scanning (ms): Min: 3.9, Avg: 4.6, Max: 6.1, Diff: 2.2, Sum: 18.4]
      [Update RS (ms): Min: 10.2, Avg: 11.6, Max: 12.6, Diff: 2.4, Sum: 46.6]
         [Processed Buffers: Min: 50, Avg: 61.0, Max: 79, Diff: 29, Sum: 244]
      [Scan RS (ms): Min: 15.5, Avg: 16.1, Max: 16.5, Diff: 1.0, Sum: 64.4]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [Object Copy (ms): Min: 32.8, Avg: 33.1, Max: 33.5, Diff: 0.6, Sum: 132.2]
      [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.1, Max: 0.1, Diff: 0.1, Sum: 0.3]
      [GC Worker Total (ms): Min: 65.4, Avg: 65.5, Max: 65.5, Diff: 0.1, Sum: 261.9]
      [GC Worker End (ms): Min: 89705543.6, Avg: 89705543.6, Max: 89705543.6, Diff: 0.1]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.5 ms]
   [Other: 4.3 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 1.8 ms]
      [Ref Enq: 0.1 ms]
      [Redirty Cards: 0.1 ms]
      [Humongous Register: 0.1 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 1.4 ms]
   [Eden: 2426.0M(2426.0M)->0.0B(2424.0M) Survivors: 30.0M->32.0M Heap: 3590.1M(4096.0M)->1166.9M(4096.0M)]
 [Times: user=0.26 sys=0.00, real=0.07 secs]
2019-10-31T07:36:18.268+0000: 89715.969: [GC pause (G1 Evacuation Pause) (young), 0.0708364 secs]
   [Parallel Time: 66.0 ms, GC Workers: 4]
      [GC Worker Start (ms): Min: 89715969.9, Avg: 89715970.0, Max: 89715970.1, Diff: 0.1]
      [Ext Root Scanning (ms): Min: 4.6, Avg: 4.7, Max: 4.8, Diff: 0.2, Sum: 18.8]
      [Update RS (ms): Min: 11.3, Avg: 11.5, Max: 12.0, Diff: 0.6, Sum: 46.2]
         [Processed Buffers: Min: 47, Avg: 62.2, Max: 74, Diff: 27, Sum: 249]
      [Scan RS (ms): Min: 16.0, Avg: 16.5, Max: 16.9, Diff: 0.9, Sum: 66.1]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [Object Copy (ms): Min: 33.0, Avg: 33.0, Max: 33.1, Diff: 0.1, Sum: 132.0]
      [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
         [Termination Attempts: Min: 1, Avg: 10.2, Max: 16, Diff: 15, Sum: 41]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.3]
      [GC Worker Total (ms): Min: 65.8, Avg: 65.9, Max: 65.9, Diff: 0.1, Sum: 263.5]
      [GC Worker End (ms): Min: 89716035.8, Avg: 89716035.9, Max: 89716035.9, Diff: 0.1]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.7 ms]
   [Other: 4.2 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 1.6 ms]
      [Ref Enq: 0.1 ms]
      [Redirty Cards: 0.2 ms]
      [Humongous Register: 0.1 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 1.4 ms]
   [Eden: 2424.0M(2424.0M)->0.0B(2426.0M) Survivors: 32.0M->30.0M Heap: 3590.9M(4096.0M)->1167.8M(4096.0M)]
 [Times: user=0.27 sys=0.00, real=0.07 secs]

jstat -gc pid 2000的部分数据如下

S0C    S1C    S0U    S1U      EC       EU        OC         OU       MC     MU    CCSC   CCSU   YGC     YGCT    FGC    FGCT     GCT
 0.0   32768.0  0.0   32768.0 2609152.0 782336.0 1552384.0   529075.5  128640.0 120812.1 15744.0 14506.7   9114  631.870   0      0.000  631.870
 0.0   32768.0  0.0   32768.0 2609152.0 1372160.0 1552384.0   529075.5  128640.0 120812.1 15744.0 14506.7   9114  631.870   0      0.000  631.870
 0.0   32768.0  0.0   32768.0 2609152.0 1830912.0 1552384.0   529075.5  128640.0 120812.1 15744.0 14506.7   9114  631.870   0      0.000  631.870
 0.0   32768.0  0.0   32768.0 2609152.0 2334720.0 1552384.0   529075.5  128640.0 120812.1 15744.0 14506.7   9114  631.870   0      0.000  631.870
 0.0   32768.0  0.0   32768.0 2609152.0 303104.0 1552384.0   530762.0  128640.0 120812.1 15744.0 14506.7   9115  631.942   0      0.000  631.942
 0.0   32768.0  0.0   32768.0 2609152.0 815104.0 1552384.0   530762.0  128640.0 120812.1 15744.0 14506.7   9115  631.942   0      0.000  631.942
 0.0   32768.0  0.0   32768.0 2609152.0 1357824.0 1552384.0   530762.0  128640.0 120812.1 15744.0 14506.7   9115  631.942   0      0.000  631.942
 0.0   32768.0  0.0   32768.0 2609152.0 1820672.0 1552384.0   530762.0  128640.0 120812.1 15744.0 14506.7   9115  631.942   0      0.000  631.942
 0.0   32768.0  0.0   32768.0 2609152.0 2320384.0 1552384.0   530762.0  128640.0 120812.1 15744.0 14506.7   9115  631.942   0      0.000  631.942
 0.0   32768.0  0.0   32768.0 2609152.0 380928.0 1552384.0   532522.0  128640.0 120812.1 15744.0 14506.7   9116  632.016   0      0.000  632.016
 0.0   32768.0  0.0   32768.0 2609152.0 989184.0 1552384.0   532522.0  128640.0 120812.1 15744.0 14506.7   9116  632.016   0      0.000  632.016
 0.0   32768.0  0.0   32768.0 2609152.0 1400832.0 1552384.0   532522.0  128640.0 120812.1 15744.0 14506.7   9116  632.016   0      0.000  632.016
 0.0   32768.0  0.0   32768.0 2609152.0 2004992.0 1552384.0   532522.0  128640.0 120812.1 15744.0 14506.7   9116  632.016   0      0.000  632.016
 0.0   32768.0  0.0   32768.0 2609152.0 88064.0  1552384.0   534125.0  128640.0 120812.1 15744.0 14506.7   9117  632.086   0      0.000  632.086
 0.0   32768.0  0.0   32768.0 2609152.0 524288.0 1552384.0   534125.0  128640.0 120812.1 15744.0 14506.7   9117  632.086   0      0.000  632.086

问题

每次YGC 70ms,其中有一半的时间耗在了Object Copy阶段,但是看Eden区每次YGC之后都降成了0,那只存在Survivor的拷贝时间(30M),需要花费30ms,这也是不正常的

请问如何分析这个情况,以及如何去进一步定位问题?

5324 阅读
请先登录,再评论

是触发了动态年龄晋级old吧

2年前
回复 QIANGLU:

晋升到old的1M多,虽然可能性不大,不过也是可能的,主要应该是s0->s1的过程

2年前回复

Eden区每次YGC之后都降成了0,其实并不意味着Eden里的都是死对象,这些对象是很可能因为survivor空间不够用而被copy到了old了

2年前
回复 你假笨:

又上了一课,多谢笨神!
找个机会Heap Down一下看看情况

2年前回复
回复 longjames:

极有可能

2年前回复
回复 qq271859852:

我也遇到类似的问题,不知道是不是survivor from -> to copy的耗时

2年前回复
查看更多