生产环境元空间内存溢出(OOM)的问题排查

目录

一、现象

二、排查过程

1.相关概念

2.定位问题

3.复现问题

a.反射对元空间的影响

b.雪花算法

4.解决问题

三、总结

---

一、现象

        下午收到业务反馈接口调用超时，其他系统调用我们系统接口等待过久引起异常。看了下接口调用的生产日志，发现接口的响应时间在五十秒左右。我们自己测试了下，也是这么长，还是必现的，那大概率就是系统自身的问题。线程占用cpu的时间短，这很容易就联想到Java虚拟机在频繁gc，我们看了下gc日志：

        又看了下info日志：

        已经在报元空间内存溢出的异常了：java.lang.OutOfMemoryError: Metaspace，当时我们把元空间的最大内存从512M调大到1G就立即重启了。

二、排查过程

1.相关概念

        Java虚拟机的元空间是保存类的元数据(Class)的，不同于堆，元空间是到服务器上申请内存的，所以如果一台服务器部署了多个应用，最好设置个上限，可以通过这两个参数设置大小：

1. -XX:MetaspaceSize=256m //初始大小
2. -XX:MaxMetaspaceSize=512m //最大值

我们生产设置的值为512M，测试环境压测的时候发现元空间内存稳定在220M左右，正常情况下是够用的，现在看就是出现问题了。

        Jdk内置了很多工具jcmd、jconsole、jvisualvm，配合下面这些参数，可以分析Java虚拟机的运行情况：

1. -XX:NativeMemoryTracking=summary //NMT内存分析
2. -XX:+UnlockDiagnosticVMOptions //启用内置工具
3. -XX:+TraceClassLoading //查看类加载信息
4. -XX:+TraceClassUnloading //查看类卸载信息

        反射调用时会加载很多中间类，用于构造Java对象或方法调用。使用反射应该慎重，并且只在没有其他代替方案时使用。

2.定位问题

        从日志看，首先com.netflix.discovery.DiscoveryClient是eureka客户端到注册中心发现和更新微服务信息的类，启动时会开启定时任务周期性轮询微服务的状态，本质就是发送get请求拉取微服务信息，并与本地已经保存的微服务进行对比，发现有变化就更新。这个过程会执行一段代码：

        可见每次轮询都会创建RequestExecutor接口的匿名实现类，如果元空间满了，生成匿名类就会报内存溢出的异常:

        这跟日志中的元空间内存溢出的溢出是对应的。而在run方法中会获取轮询任务的Future，然后get等待：

        现在task没法创建，自然就报了timeout超时异常了。这样就能明确定位是由于元空间内存满了导致频繁gc，而引起接口调用超时。

3.复现问题

        刚开始我们觉得是线上的并发量很大，处理的请求过多，导致我们的反射代码大量执行，从而加载了很多中间类，于是在测试环境进行压测，结果发现qps为100时元空间大概稳定在220M左右，然后每次波动很小，上涨很慢。之后又去生产看了接口调用信息，发现qps在39左右，因此不是高并发引起。

        于是我们就仔细看了那段时间所有日志，发现有个地方报了主键冲突的异常：

        这里我有两个猜想，一是不断地报主键冲突的异常对元空间内存占用会产生影响吗，二是为什么会报主键冲突的异常，不管怎样这个异常肯定要解决。

a.反射对元空间的影响

        Java虚拟机底层是c++实现的，不太好看懂。网上的说法也是众说纷纭，没有统一的标准，而且Java内存溢出也很少见。我就打算自己来验证了。

        首先我到生产环境把出现主键冲突到内存溢出这段时间的接口都查出来了，然后使用postman为接口设置调用次数，延时为25ms，模拟qps为40。在本地的代码中手动设置实体类id为数据库中已有的主键，我一直用jconsole观察元空间内存，发现内存一直在上涨。 再运行了一段时间后，就复现生产环境内存溢出的问题了！

        此时通过 jcmd  220096  GC.class_stats  >> class10.txt 指令收集虚拟机的类加载信息，就能发现加载了大量的sun.reflect包下的类，这些正是跟反射相关的类，用于反射的方式构造实例对象和方法调用。从日志可以看到，如果jdbc抛出了异常，就会有大量的发射调用。

        所以我得出的结论就是：此次元空间内存溢出(OOM)就是因为不断地产生主键冲突的异常引起的。

b.雪花算法

        我们的主键不是数据库生产，而是我们通过雪花算法生成的。我先看了实体类中id所有set方法调用的地方，发现这个值只来自于雪花算法的实现方法，那得仔细看这个方法了。

    我们的id是由generate()方法生成的，雪花算法是由nextId()实现的，timeStr是"yyMMddHHmmss"格式表示的时间字符串，这个方法的逻辑就是如果同一秒的线程拿到锁执行nextId()方法序列号就会加加，到新的一秒就会置0，而我们的id就是由"yyMMddHHmmss"格式表示的时间字符串和nextId()方法返回的值合并的，所以一般情况应该是不会重复的。

        但也有特殊情况，第一是服务器的时间变化了，就会生成重复的id，虽然这个概率很低。第二个就是多线程同步执行的情况了，看图说话吧，整个过程分以下几步：

1. 线程1在12:00:00.990获取到锁执行nextId()方法的时候，线程2在12:00:00.995进来了，线程3在12:00:01.005进来了，假设方法的执行时长为20ms。
2. 到12:00:01.010方法执行完毕，线程1生成的id为”20231015120000”+”0000”，此时释放锁；
3. 由于synchronized是公平锁，所以要么线程2获取到锁，要么线程3获取到锁，如果线程2获取到锁，生成的id就是”20231015120000”+”0001”，再然后线程3拿到锁生成的id是”20231015120001”+”0000”，id是各不相同的，分别为：

1. ”20231015120000”+”0000”
2. ”20231015120000”+”0001”
3. ”20231015120001”+”0000”

1. 但是如果是线程3先拿到锁呢，那么线程3拿到锁后生成id是”20231015120001”+”0000”，线程2再拿到锁生成的id就是”20231015120000”+”0000”，此时生成所有的id是：

1. ”20231015120000”+”0000”
2. ”20231015120000”+”0000”
3. ”20231015120001”+”0000”

        很显然生成重复的id了，在插入到数据库时就会引起主键冲突，进而持续抛出异常，大量占用元空间，最后导致元空间内存溢出。

        为什么会产生这个问题，因为线程抢占锁是随机且公平的，不是按照时间顺序的，就是说可能后一秒的线程执行完了，锁可能会让给前一秒在等待的线程。

4.解决问题

        刚开始打算使用Atomic原子变量解决，就写个下面这个版本：

        意思是只要有请求进来就加加，只要一秒内的请求数不超过MAX_SEQUENCE(8191)就不会重复结果压测发现还是生成了重复的id，上面的nextIdAtomic()效率是很高，但问题是sequence是单例bean的属性，即便计算出sequence的值，在return之前如果有其他线程进来了拿到的就是跟当前线程一样的值。

        最终我们的雪花算法实现如下:

        逻辑是每次获取当前毫秒时间戳，如果是同一毫秒的线程序列号就加加，加到512为止(如果加到512以上还是会重复，但是概率几乎为0，因为1s内得有500*60=30000个请求进来)，如果不同毫秒的线程就置为0，压测了20万个线程，分别设置qps为100、200、1000均正常。

三、总结

        通过这次生产问题的解决，自己也积累了一点排查问题的经验。首先解决问题的时候一定要学会分析，问题是什么，怎么产生的，怎么导致的，要一层一层的排查。然后就是一定要自己动手操作，对出现的现象进行观察思考，同时要利用好和问题相关的资源。最后就是平时的积累很重要，因为我不怎么熟悉jvm，很多技术也是在这个问题中第一次使用，就比较耽误时间，所以平时不要轻易忽视学习积累的机会，说不定哪天就用上了。