问题背景
在对首页接口进行压测时,发现tps一直上不去,甚至维持在5左右,请求失败率高达90% 超过5并发机器会直接下线。需要讲tps提升到200。需要查看并优化问题
排查过程
- 排查代码中发现,在获取某些上下文数据时,采用了多线程的方式进行获取,每一条请求大概会开启10条左右的线程去获取资源,但是该线程池最大只有50条线程。遂想监控下该线程池的使用情况
- 在预发机器中,登陆arthas,使用dashboard命令查看线程的忙碌情况,查看后发现,最忙碌的线程并不是业务内创建的线程,而是log4j的线程和GC的线程,并且gc次数在猛增。一次压测3分钟,发生了10余次fullgc,刚开始以为是预发机器内存配置过小原因,从1g调整为2g后数据依旧如此。于是dump 了堆快照进行内存分析
- 可以看到在堆内存中,一个叫RingBuffer的对象占据了几乎80%的内存,于是去查询该对象所在的包以及包管理
结合监控线程的情况,可以断定,该内存是由于log4j所占用的,于是发现预发环境的线上homepage日志开关没有关,关闭日志开关后jvm恢复正常,压力测试也可以顺利完成。
原因分析
根据ring buffer对象归属的类中发现,它是由disruptor使用的对象,首先聊一下disruptor是一个什么东西。
Disruptor是英国外汇交易公司LMAX开发的一个高性能队列,研发的初衷是解决内存队列的延迟问题(在性能测试中发现竟然与I/O操作处于同样的数量级)。基于Disruptor开发的系统单线程能支撑每秒600万订单。
Disruptor 不同于kafka是解决业务间消息传递的队列。Disruptor是单纯为了解决内存数据队列而产生的。在JDK中主要对标的是ArrayBlockingQueue,在ArrayBlockingQueue中,主要是通过加锁的方式来防止多线程的并发问题,而Disruptor采用了CAS的方式,避免了加锁产生的开销。
多个生产者的情况下,会遇到如何防止多个线程重复写同一个元素的问题。Disruptor的解决方法是,每个线程获取不同的一段数组空间进行操作。这个通过CAS很容易达到。只需要在分配元素的时候,通过CAS判断一下这段空间是否已经分配出去即可。如果已经被分配出去,则通过while循环的方式申请下一段内存空间使用
在Disruptor中可以指定一些消费者waitStrategy来制定当无任务时 消费线程的情况
对Disruptor就介绍这么多,有兴趣的可以查看该文章查看详情;
在Log4j中,我们采用异步方式进行磁盘写入,当打印日志时,Log4j先将日志通过Disruptor写入内存中,再由消费线程进行数据的落盘,而RingBuffer对象即是Disruptor框架中主要的数据存储对象。可以认定,上面所说的问题是内存数据写入过多,导致堆内存溢出
在DisruptorUtil.RINGBUFFER_DEFAULT_SIZE 变量中 可以发现默认RingBuffersize 为 256* 1024
根据apache 的issues 可以看出,这个size并不是指对象的大小,而是Ringbuffer的插槽大小,每一条日志对应一个插槽,即当每条日志都有10K时,频繁打印日志填满插槽 可能会在内存 最多填充 10 * 1024 * 246 KB的内存。
通过排查相关日志,发现有部分异常日志打印,单条日志近400KB
解决办法
- 尽量不要打印整个对象。如果业务必须要打印整个对象,则控制打印日志的长度,不要打印太长的日志
- 通过配置 修改 DisruptorUtil.RINGBUFFER_DEFAULT_SIZE 的配置值,修改插槽的大小,可以控制内存,当插槽满时,线程会阻塞,也可以配置丢弃日志,Log4j会丢弃INFO DEBUG TRACE级别的日志