【Java】OOM_wrk性能测试导致的JVM堆内存溢出问题排查

问题描述

笔者使用wrk对API做性能测试，经过半个小时的压力测试，发现API的响应时间高达几秒，JVM老年代的使用率达到99%且GC后使用率没有明显下降。笔者认为这个问题可能是内存泄露导致的。于是在开发环境模拟此问题。

笔者在开发环境中设置的相关参数如下。堆内存设置200MB且开启GC日志等，便于分析日志信息。

version: '3'
services:
  spindle_backend_model_dev:
    build: /data/data_spindle_dev/dockerImages/application/spindle_backend_model_dev
    image: spindle_backend_model_dev:1.0.0
    container_name: spindle_backend_model_dev
    ports:
      - "9094:9094"
    extra_hosts:
      - "mysql_ip:127.0.0.1"
      - "redis_ip:127.0.0.1"
      - "cassandra_ip:127.0.0.1"
      - "model_ip:127.0.0.1"
    network_mode: "host"
    logging:
      driver: "json-file"
      options:
        max-size: "200m"
        max-file: "1"
    volumes:
      - /etc/localtime:/etc/localtime
      - /etc/timezone:/etc/timezone
      - /data/data_spindle_dev/dockerImages/application/spindle_backend_model_dev/data/log:/data/log
      - /data/data_spindle_dev/dockerImages/application/spindle_backend_model_dev/data/jvmLog:/data/jvmLog
      - /data/data_spindle_dev/dockerImages/application/spindle_backend_model_dev/data/configuration:/data/configuration
    environment:
      - JAVA_OPTS=-Xms200m -Xmx200m   -Dlog4j2.formatMsgNoLookups=true   -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/data/jvmLog  -XX:+PrintGCDateStamps  -XX:+PrintHeapAtGC   -XX:+PrintGCDetails -XX:+PrintTenuringDistribution -XX:+PrintGCApplicationStoppedTime  -XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=10 -XX:GCLogFileSize=50M -Xloggc:/data/jvmLog/gc-%t.log
      - SPRING_PROFILES_ACTIVE=prod
    privileged: true

FROM openjdk:8
RUN mkdir /data
WORKDIR /data
ADD action-1.0-SNAPSHOT.jar  backend.jar
ADD  arthas.tar .
ENTRYPOINT exec java ${JAVA_OPTS} -Djava.security.egd=file:/dev/./urandom -jar /data/backend.jar

相关工具

• 在线GC日志分析工具gceasy
• 在线堆内存快照分析工具heaphero
• GCViewer
• JProfiler

环境

• JDK1.8
• JVM 25.275-b01
• Springboot 2.1
• wrk 4.2.0

实践案例

使用wrk压测十几分钟后，问题果然又复现了。下面就进入问题排查流程。

1. 先看Java程序进程的堆内存整体状态。
   老年代占用率达到98.1%，说明老年代空间分配太少或者是存在内存泄露。
   年轻代Eden使用率是100%，说明每次创建的新对象都会将Eden塞满，说明Eden或者年轻代设置的偏小。

2. 步骤1只能确认在某一时刻的内存使用状况，并不能反映出GC整体趋势。需要根据日志查看GC前后的内存使用率来确定是否是内存泄露。下图可知，老年代经过GC后没有回收到一丁点空间，笔者此时确定是程序中存在内存泄露。

3. 性能测试一段时间后发现，使用GCViewer展示日志。红色表示堆内存容量，蓝色表示已使用堆内存，黑色代表FGC，下图可知程序后期都在执行FGC，这肯定是内存泄露。

4. 使用jmap获取JVM的堆内存快照信息。
   jmap -dump:live,format=b,file=/data/jvmLog/heap_0101.hprof 1
JProfiler解析后发现其中一个大对象占用了62.2%的堆内存空间。

于是谷歌一下对象org.apache.catalina.session.StandardManager.sessions到底是什么用途。
protected Map<String, Session> sessions = new ConcurrentHashMap<String, Session>();
其目的是存放session。用户第一次请求后会将此sessionid信息放入sessions，后续请求会从sessions中查找此session是否存在，存在就使用；不存在就创建一个新的sessionid加入sessions。

5. 针对当前session问题，笔者先使用了一个临时方案即设置session有效期，例如有限期2s。

server:
  port: 9095
  servlet:
    session:
      timeout: 2

6. 再次进行性能测试后查看gc以及堆信息。大对象不存在了，堆内存已经得到有效回收，没有发生严重的FGC现象。

7. session到底是什么用途，笔者先做一个简单的描述。

• sessionid是一个会话的key，浏览器第一次访问服务器会在服务器端生成一个session，有一个sessionid和它对应。tomcat生成的sessionid叫做jsessionid。
• 客户端只保存sessionid到cookie中，而不会保存session。session销毁只能通过invalidate或超时，关掉浏览器并不会删除session。
• 创建session：sessionid第一次产生是在服务端程序调用 HttpServletRequest.getSession(true)。sessionid生成方法使用随机数+时间+JVMID
• 删除session：超时；程序调用HttpSession.invalidate()；程序关闭；
• session存放位置：默认服务器端的内存中，也可以放入第三方存储中。

总结

1. 本文主要是基于wrk做一些简单的性能测试，并根据JVM反映出来的问题使用临时方案解决问题。
2. 笔者后续要解答的问题包括：session在连续的两个请求之间充当什么作用；session的工作流程是什么；如果网站访问量级很大，如何进行session管理；session与token有什么区别；程序中哪些地方使用session，哪些地方使用token；是否还有其他替代session的方案。