背景

企业白条应用在登录应用后报用户状态查询异常，查看日志发现请问到达服务应用后，查询用户状态处理时间过长导致到达了dubbo接口超时时间

环境

系统：Red Hat Enterprise Linux 6.7
内存：4G
磁盘：系统盘20G，数据盘30G
CPU：双路 Intel E7 v3（10核20线程）

  1. ## 查看系统信息
  2. lsb_release -a
  3. ## 查看内存信息
  4. free -G
  5. ## 查看磁盘信息
  6. dh -f
  7. ## 查看CPU信息
  8. more /proc/cpuinfo
  9. top

服务器情况

cpu占用：大于100%
内存占用：3710m

应用启动参数

  1. -Djava.io.tmpdir=/data/dataTemp -XX:+UseCompressedOops -Xms3g -Xmx3g -XX:MetaspaceSize=256m -XX:MaxMetaspaceSize=1024m -XX:NewSize=2g -XX:MaxNewSize=2g -XX:+UseCMSInitiatingOccupancyOnly -XX:+PerfDataSaveToFile -XX:SurvivorRatio=10 -Xloggc:/data/dataLogs/gc/gc.log -verbose:gc -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+UseConcMarkSweepGC -XX:+UseCMSCompactAtFullCollection -XX:+CMSClassUnloadingEnabled -XX:+DisableExplicitGC -XX:CMSInitiatingOccupancyFraction=80 -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/data/dataLogs/dump -XX:ParallelGCThreads=3

参数分析

  • Djava.io.tmpdir：默认临时文件放置地址
  • -XX:+UseCompressedOops：压缩指针对象，使jvm使用32位指针对象
  • -Xms3g：最小堆内存为3g
  • -Xmx3g：最大堆内存为3g（最小堆内存和最大堆内存一致，可以减小堆计算空间时的损耗）
  • -XX:MetaspaceSize=256m：元空间内存大小为256m
  • -XX:MaxMetaspaceSize=1024m：最大元空间内存大小为1024m
  • -XX:NewSize=2g：新生代内存指定为2g
  • -XX:MaxNewSize=2g：新生代最大内存指定为2g
  • -XX:CMSInitiatingOccupancyFraction=80：指定CMS在内存占用率达到80%时开始GC（因为CMS会有浮动垃圾，所以一般会较早启动gc）
  • -XX:+UseCMSInitiatingOccupancyOnly：指定用设置的回收阈值，如果不指定，JVM在第一次使用设定值后会自动调整（以上两参数一般需要同时使用，已达到减低CMS频率或增加CMS频率、减少GC时长）
  • -XX:+PerfDataSaveToFile：应用退出时，保存jstat二进制文件，并设置文件名为hsperfdata_<进程id>
  • -XX:SurvivorRatio=10：指定新生代内存比例为10:1:1，所以伊甸园区内存为2g*10/12 = 1.67g
  • -Xloggc:/data/dataLogs/gc/gc.log：gc日志保存到/data/dataLogs/gc
  • -verbose:gc：输出虚拟机中的gc详细情况
  • -XX:+PrintGCDateStamps：输出GC的时间戳，日期格式为：2013-05-04T21:53:59.234+0800
  • -XX:+PrintGCDetails：打印GC详细信息（相对-verbose:gc为非稳定版，可能在未通知的情况下删除）
  • -XX:+UseConcMarkSweepGC：使用CMS垃圾回收器，用于并行标记清除算法回收老年代垃圾
  • -XX:+UseCMSCompactAtFullCollection：指定是CMS启用MSC（Mark Sweep Compact）算法进行压缩内存堆（一般与-XX:CMSFullGCsBeforeCompaction=n同时使用（0为n的默认值，指每次fullgc都压缩））
  • -XX:+CMSClassUnloadingEnabled：声明对永久代进行垃圾回收（CMS默认不会对永久代进行垃圾回收）
  • XX:+DisableExplicitGC：完全忽略系统的GC调用
  • -XX:CMSInitiatingOccupancyFraction=80：表示老年代在使用率达到80%时启动垃圾回收
  • -XX:+HeapDumpOnOutOfMemoryError：当产生oom时自动产生dump文件
  • -XX:HeapDumpPath=/data/dataLogs/dump：dump文件生成地址
  • -XX:ParallelGCThreads=3：指定并发垃圾回收的线程数（(ParallelGCThreads+3)/4）

    日志打印

    业务日志打印

    在gc日志打印的第一次FullGC时间，大部分是kafka发送消息之后，也会有部分其他业务处理到一半的

    GC日志打印

线程快照信息

优化思路

现象分析

  • 使用jps获取java进程id
  • 使用jstat -gc <进程id> 3000实现3秒输出一次gc情况，可以在15次左右youngGC后，新生代对象转移到老年代并不断开始堆积到80%，然后开始疯狂FullGC
  • 使用jmap -dump:format=b,file=dump.hprof -F <进程id>生成线程快照
  • 由线程快照信息分析对象的引用链可见，堆中有30%左右内存为kafka-producer通过nio发送消息产生的byte[]对象，并且是由于对象没有释放引用，不断堆积在老年代到达80%，且不能回收，导致不断FullGC引起应用停滞
  • 多日业务日志记录的第一次FullGC也基本指向kafka

但不同的是，日志中基本是在准备发送kafka就停顿了，有业务需求是接收到上游的处理结果kafka后做本地处理 并通过kafka通知到自己的下游。

  • 代码查看：由于兼容生产环境多kafka service的情况进行了kafkaProducer的改造，每次会创建一个指定server的producerTemplate

    优化思路

  • 将每次都会生成producerTemplate改造成单例模式，将kafkaServer作为键，缓存不同server的template到本地，按需获取template进行业务处理

  • 将发送ack从all调整到1，all表示集群全部机器接收到信息后应答，1表示只要有一台机器接收到消息就应答
  • 增加ProducerListener进行消息发送结果记录

以下为调整代码：多码预警

  1. // 使用单例模式优化template获取
  2. public KafkaTemplate<Integer, String> kafkaTemplate() {
  3.     KafkaTemplate template = kafkaTemplateMap.get(getKafkaInfo().getServers());
  4.     if (Assert.isNull(template)) {
  5.         LOCK.lock();
  6.         try {
  7.             if (Assert.isNull(kafkaTemplateMap.get(getKafkaInfo().getServers()))) {
  8.                 template = new KafkaTemplate<String, String>(producerFactory(), Assert.isNull(getKafkaInfo().getAutoFlush()) ? DEFAULT_AUTO_FLUSH : getKafkaInfo().getAutoFlush());
  9.                 template.setProducerListener(kafkaProducerListener);
  10.                 kafkaTemplateMap.put(getKafkaInfo().getServers(), template);
  11.             } else {
  12.                 template = kafkaTemplateMap.get(getKafkaInfo().getServers());
  13.             }
  14.         } finally {
  15.             LOCK.unlock();
  16.         }
  17.     }
  18.     return template;
  19. }
  1. // 增加ProducerListenter
  2. @Slf4j
  3. @Component
  4. public class KafkaProducerListener implements ProducerListener {
  6.     @Override
  7.     public void onSuccess(ProducerRecord producerRecord, RecordMetadata recordMetadata) {
  8.         this.onSuccess(producerRecord.topic(), producerRecord.partition(), producerRecord.key(), producerRecord.value(), recordMetadata);
  9.         log.info("topic:{}, partition:{}, key:{}, value:{}, send success", producerRecord.topic(), producerRecord.partition(), producerRecord.key(), producerRecord.value());
  10.     }
  12.     /**
  13.      * 发送消息错误后调用
  14.      */
  15.     @Override
  16.     public void onError(ProducerRecord producerRecord, Exception exception) {
  17.         this.onError(producerRecord.topic(), producerRecord.partition(), producerRecord.key(), producerRecord.value(), exception);
  18.         log.info("topic:{}, partition:{}, key:{}, value:{}, send failed", producerRecord.topic(), producerRecord.partition(), producerRecord.key(), producerRecord.value());
  19.         exception.printStackTrace();
  20.     }
  22.     /**
  23.      * 是否开启发送监听
  24.      *
  25.      * @return true开启，false关闭
  26.      */
  27.     @Override
  28.     public boolean isInterestedInSuccess() {
  29.         return true;
  30.     }
  31. }