一、现象

2023.10.17下午收到业务反馈，说是接口调用超时，进件系统和核心系统调用外数系统接口时等待过久，引起系统异常。然后我们看了下接口调用的日志，确实接口的响应时间在五十秒左右。我们自己测试了下，发现也是这么长，这是必现的，大概率就是系统自身的问题。很容易就联想到Java虚拟机内在频繁gc，导致Java进程运行受阻，处理时间过长，然后我们就看到报元空间内存溢出的异常了：java.lang.OutOfMemoryError: Metaspace，当时我们调大元空间的内存就立即重启了。

 

二、排查过程

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客户端发现注册中心的类，eureka客户端启动时会开启定时任务周期性轮询微服务的状态，本质就是发送get请求拉取微服务信息并与本地已经保存的微服务进行对比，发现有变化就更新，这里面会执行一段代码：

可见每次轮询都会创建RequestExecutor接口的匿名实现类，如果元空间满了，就会报内存溢出的异常，这是在DiscoveryClient类的fetchRegistry方法中报的，日志中的Timeout则是因为无法创建匿名类导致Future无法返回，这样就能明确的定位是由于元空间内存满了导致频繁gc，而引起的线上问题。

1. 复现问题

刚开始我们觉得是线上的并发量很大，处理的请求过多，导致我们的反射代码大量执行，从而加载了很多中间类，于是我们进行了压测，结果发现元空间大概稳定在220M左右，然后每次波动很小，上涨很慢。之后去生产看了接口调用信息，发现qps在39左右，因此不是高并发引起。之后我们仔细看了日志，发现在之前就一直报主键冲突的异常。我们用的是Oracle数据库，主键是通过雪花算法生成的。

这里我想到两个问题，一是不断地报主键冲突的异常对元空间内存占用造成的影响是什么，二是为什么会报主键冲突的异常。

a.反射对元空间的影响

Java虚拟机底层是c++实现的，代码看不懂的。网上的说法也是众说纷纭，每个统一的标准，而且Java内存溢出也是很少出现。我就打算自己来验证了。首先我到生产环境把出现主键冲突到内存溢出这段时间的接口都查出来了，然后使用postman为接口设置调用次数，延时为25ms，模拟qps为40的调用环境。在本地的代码中手动设置实体类主键为数据库中已有的主键，结果就复现了生产环境内存溢出的问题了。

我通过 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是各不相同的；但是如果是线程3先拿到锁呢，那么线程3拿到锁后生成id是”20231015120001”+”0000”，线程2再拿到锁生成的id就是”20231015120000”+”0001”，就跟线程1产生的id重复了，也就会在插入到数据库时引起主键冲突了，进而抛出异常，进而持续大量占用元空间，导致元空间内存溢出。

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

1. 解决问题

刚开始打算使用Atomic原子变量解决，就写个下面这个版本，意思是只要有请求进来

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

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

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

三、总结

通过这次生产问题的解决，自己也积累了一点排查问题的经验。首先解决问题的时候一定要学会分析，问题是什么，怎么产生的，怎么导致的，要一层一层的排查。然后就是大胆猜想，小心证明，一定要自己动手操作，容易产生灵感。现有的数据一定要好好利用。最后就是平时的积累很重要，因为不怎么熟悉jvm，所以很多工具还是现学现卖的，就比较耽误时间，所以平时不可以忽视学习积累的机会。