性能问答>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,这也是不正常的

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

5459 阅读
请先登录,查看10条精彩评论吧
快去登录吧,你将获得
  • 浏览更多精彩评论
  • 和开发者讨论交流,共同进步