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，这也是不正常的

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

问题

本月精选性能专题

本月精选线上案例

本月精选原创好文

联系我们

网媒渠道

友情链接