扫码关注公众号:芋道源码

发送: 百事可乐
获取永久解锁本站全部文章的链接

《Dubbo 实现原理与源码解析 —— 精品合集》 《Netty 实现原理与源码解析 —— 精品合集》
《Spring 实现原理与源码解析 —— 精品合集》 《MyBatis 实现原理与源码解析 —— 精品合集》
《Spring MVC 实现原理与源码解析 —— 精品合集》 《数据库实体设计合集》
《Spring Boot 实现原理与源码解析 —— 精品合集》 《Java 面试题 + Java 学习指南》

摘要: 原创出处 https://my.oschina.net/u/3627055/blog/2995973 「rock-man」欢迎转载,保留摘要,谢谢!


🙂🙂🙂关注**微信公众号:【芋道源码】**有福利:

  1. RocketMQ / MyCAT / Sharding-JDBC 所有源码分析文章列表
  2. RocketMQ / MyCAT / Sharding-JDBC 中文注释源码 GitHub 地址
  3. 您对于源码的疑问每条留言将得到认真回复。甚至不知道如何读源码也可以请教噢
  4. 新的源码解析文章实时收到通知。每周更新一篇左右
  5. 认真的源码交流微信群。

背景

​ 生产环境有二台阿里云服务器,均为同一时期购买的,CPU、内存、硬盘等配置相同。具体配置如下:

节点 CPU 内存 硬盘 其它
A 2CPU 4G 普通云盘 Centos6.4 64位+JDK1.8.0_121
B 2CPU 4G 普通云盘 Centos6.4 64位+JDK1.8.0_121

​ 由于这二服务器硬件和软件配置相同,并且运行相同的程序,所以在Nginx轮询策略均weight=1,即平台的某个流量由这二台机器平分。

​ 有一次对系统进行例行检查,使用PinPoint查看下服务器”Heap Usage”的使用情况时,发现,在有一个系统Full GC非常频繁,大约五分钟一次Full GC(如果不明白Full GC的什么意思的,请自行百度),吓我一跳。这么频繁的Full GC,导致系统暂停处理业务,对系统的实时可用性大打折扣。我检查了一下Tomcat(Tomcat8.5.28)配置,发现在tomcat没有作任何关于JVM内存的设置,全部使用默认模式。由于这二服务器硬件和软件配置相同,并且运行相同的程序,所以在Nginx轮询策略均weight=1,即平台的某个流量由这二台机器平分。

GC数据

​ 在业务峰期间,通过PinPoint观察的A、B节点的”Heap Usage”使用情况,分别进行以下几个时间段数据。

​ 3小时图:

​ 上图B系统在三个小时内,一共发生了22次Full GC,大约每8分钟进行一次Full GC。每次Full GC的时间大概有150ms左右,即B系统在三个小时内,大约有3300ms暂停系统运行。从上图来看,堆的空间最大值在890M左右,但在堆空间的大小大约200M就发生Full GC了,从系统资源的利用角度来考虑,这个使用率太低了。

img

​ 上图A系统在3个小时内,一共发生了0次Full GC,嗯,就是没有任何停顿。 在这3小时,系统一直在处理业务,没有停顿。堆的总空间大约1536m,目前堆的空间大于500M。

​ 6小时图:

​ 上图B系统在6个小时的数据统计和3个小时很像,6个小时内一共发生了N次Full GC,均是堆的空间小于200M就发生Full GC了。

​ 上图A系统在6个小时内,一共发生了0次Full GC,表现优秀。

12小时

​ 上图B系统在12个小时内,一共发生了N次Full GC,左边Full GC比较少,是因为我们的业务主要集中白天,虽然晚上属于非业务高峰期间,还是有Full GC。

​ 上图A系统在12个小时内,一共发生了0次Full GC,表现优秀。

GC日志

​ 看下gc.log文件,因为我们两台服务器都输出了gc的详细日志,先看下B系统的Full GC日志。

​ 上图全部是” [Full GC (Ergonomics)”日志,是因为已经去掉” GC (Allocation Failure”日志,这样更方便观察和分析日志,选取GC日志文件最后一条Full GC日志。

​ 2018-12-24T15:52:11.402+0800: 447817.937: [Full GC (Ergonomics) [PSYoungGen: 480K->0K(20992K)] [ParOldGen: 89513K->69918K(89600K)] 89993K->69918K(110592K), [Metaspace: 50147K->50147K(1095680K)], 0.1519366 secs] [Times: user=0.21 sys=0.00, real=0.15 secs]

​ 可以计算得到以下信息:

​ 堆的大小:110592K=108M

​ 老生代大小:89600K=87.5M

​ 新生代大小:20992K=20.5M

​ 分析:这次Full GC是因为老年代对象占用的空间的大小已经超过老年代容量 ([ParOldGen: 89513K->69918K(89600K)])引发的Full GC。是因为分配给老年代的空间太小,远远不能满足系统对业务的需要,导致老年代的空间常常被占满,老年代的空间满了,导致的Full GC。由于老年代的空间比较小,所以每次Full GC的时间也比较短。

​ A系统日志,只有2次Full GC,这2次GC均发生在系统启动时:

​ 7.765: [Full GC (Metadata GC Threshold) [PSYoungGen: 18010K->0K(458752K)] [ParOldGen: 15142K->25311K(1048576K)] 33153K->25311K(1507328K), [Metaspace: 34084K->34084K(1081344K)], 0.0843090 secs] [Times: user=0.14 sys=0.00, real=0.08 secs]

​ 可以得到以下信息:

​ 堆的大小:1507328K=1472M

​ 老生代大小:89600K=1024M

​ 新生代大小:20992K=448M

​ 分析:A系统只有系统启动才出现二次Full GC现象,而且是” Metadata GC Threshold”引起的,而不是堆空间引起的Full GC。虽然经过一个星期的观察,A系统没有Full GC,但一旦发生Full GC时间则会比较长。其它系统增加发现过,1024M的老年代,Full GC持续的时间大约是90ms秒。所以看得出来推也不是越大越好,或者说在UseParallelOldGC收集器中,堆的空间不是越大越好。

分析与优化

总体分析:

  1. B系统的Full GC过于频繁,是因为老生代只有约108M空间,根本无法满足系统在高峰时期的内存空间需求。由于ParOldGen(老年代)常常被耗尽,所以就发生Full GC事件了。
  2. A系统的堆初始空间(Xms)和堆的最大值(Xmx)均为1536m,完全可以满足业务高峰期的内存需求。

优化策略:

  1. B系统先增加堆空间大小,即通过设置Xms、 Xmx值增加堆空间。直接把Xms和Xmx均设置为1024M。直接堆的启动空间(Xms)直接设置为堆的最大值的原因是:因为直接把Xms设置为最大值(Xmx)可以避免JVM运行时不停的进行申请内存,而是直接在系统启动时就分配好了,从而提高系统的效率。把Xms(堆大小)设置为1024M,是因为采用JDK的建议,该建议通过命令得到” java -XX:+PrintCommandLineFlags -version” 。img其中,“-XX:MaxHeapSize=1004719104”,即Xmx为1024M,其它建议暂时不采纳。所以综合下来的B系统的JVM参数设置如下:export JAVA_OPTS="-server –Xms1024m -Xmx1024m -XX:+UseParallelOldGC -verbose:gc -Xloggc:../logs/gc.log -XX:+PrintGCDetails -XX:+PrintGCTimeStamps"

  2. A系统JVM参数设置保持不变,以便观察系统运行情况,即:export JAVA_OPTS="-server -Xms1536m -Xmx1536m -XX:+UseParallelOldGC -verbose:gc -Xloggc:../logs/gc.log -XX:+PrintGCDetails -XX:+PrintGCTimeStamps"

  3. 将A、B节点系统的JVM参数采用2套参数,是为了验证A或B的参数更适合实际情况。

文章目录
  1. 1. 背景
  2. 2. GC数据
  3. 3. GC日志
  4. 4. 分析与优化