垃圾回收G1总结

问题点
线上tomcat监控发现有2s作用不响应请求，导致tomcat抛出504

启动配置：

java -server -Xms4g -Xmx4g -XX:+UseG1GC -XX:G1ReservePercent=25 -XX:SoftRefLRUPolicyMSPerMB=0 -XX:+DisableExplicitGC -XX:+ParallelRefProcEnabled -Xloggc:/目录/log/gc_%p.log -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintGCApplicationStoppedTime -XX:+PrintTenuringDistribution -XX:+PrintAdaptiveSizePolicy -XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=5 -XX:GCLogFileSize=30m -jar application-1.0.0.jar --spring.profiles.active=online --server.port=8080

gc日志：

2018-12-23T19:09:25.363+0800: 270882.778: [GC pause (G1 Evacuation Pause) (young)
   [Parallel Time: 11.8 ms, GC Workers: 28]
      [GC Worker Start (ms): Min: 231342887.2, Avg: 231342887.6, Max: 231342887.8, Diff: 0.6]
      [Ext Root Scanning (ms): Min: 1.7, Avg: 4.1, Max: 11.0, Diff: 9.3, Sum: 115.4]
      [Update RS (ms): Min: 0.0, Avg: 2.4, Max: 4.5, Diff: 4.5, Sum: 67.0]
         [Processed Buffers: Min: 0, Avg: 8.8, Max: 25, Diff: 25, Sum: 245]
      [Scan RS (ms): Min: 0.0, Avg: 0.2, Max: 0.4, Diff: 0.3, Sum: 4.9]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [Object Copy (ms): Min: 0.0, Avg: 1.0, Max: 1.6, Diff: 1.6, Sum: 29.0]
      [Termination (ms): Min: 0.0, Avg: 3.0, Max: 3.3, Diff: 3.3, Sum: 83.4]
         [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 28]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.2, Max: 0.4, Diff: 0.4, Sum: 4.2]
      [GC Worker Total (ms): Min: 10.5, Avg: 10.9, Max: 11.1, Diff: 0.7, Sum: 303.9]
      [GC Worker End (ms): Min: 231342898.3, Avg: 231342898.4, Max: 231342898.6, Diff: 0.3]

      [Code Root Fixup: 0.3 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.7 ms]
   [Other: 119.8 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 116.6 ms]
      [Ref Enq: 0.7 ms]
      [Redirty Cards: 0.4 ms]
      [Humongous Register: 0.2 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 1.4 ms]
   [Eden: 1922.0M(1922.0M)->0.0B(1922.0M) Survivors: 6144.0K->6144.0K Heap: 3064.0M(4096.0M)->1141.9M(4096.0M)]
 [Times: user=0.99 sys=0.05, real=0.14 secs]

通过gc日志发现是Object Copy (ms)阶段耗时严重，应该是eden区有大对象没有释放导致。
关于GC1日志具体参数如下：

• Parallel Time ：stop the word 的时间
• GC Workers：并行GC执行的worker数
• [Eden: 1922.0M(1922.0M)->0.0B(1922.0M) Survivors: 6144.0K->6144.0K Heap: 3064.0M(4096.0M)->1141.9M(4096.0M)]
  代表ygc触发，eden区域已满，回收之后变为0，survivors区空间回收前后值未变，heap区回收后变为1141.9M
• [Times: user=0.99 sys=0.05, real=0.14 secs]
  user 实际使用时间包括用户代码处理时间
  sys 系统cpu使用或者等待时间
  real 实际使用时间

参考：
参考文章1
参考文章2
参考文章3