Jedis的socket内存泄露问题排查

本文是关于Jedis的socket内存泄露问题排查的分享。

背景

我负责的业务线上有N台机器。其中有一台会缓慢的出现Socket内存泄露。具体表现为在jmap时会常常看到如下类排名很靠前。

5: 274623 30757776 java.net.SocksSocketImpl 
8: 274621 13181808 java.net.SocketInputStream 
9: 274621 13181808 java.net.SocketOutputStream 
17: 274621 8787872 java.net.Socket 
21: 274668 6592032 java.net.Inet4Address

从占用数量以及内存情况来说。其实完全是可以接受的。但是不能理解的是为什么就单独这台机器占用偏高。其他机器也有一定的数量，但是和这台机器差别较多。

STEP0

这一台机器唯一和别的机器不同的是：

该机器周期性的在本机进程内执行一些数据逻辑。每5分钟调度一次，每次大概执行1分多钟。所以相比其他机器，他的YGC相对会频繁一点。大约10秒左右触发一次。而其他机器大概是1分钟触发一次。

STEP1

既然创建了这么多的socket相关对象。那需要看看是谁在不停的创建。这里可以使用开源的btrace或者其他instrument工具进行运行时监控(PS: 如果对于instrument和agent感兴趣的可以看此文 如何开发一款 java 应用运行时的监控程序 https://juejin.im/entry/5bd7f9156fb9a05d185f3ae8 )。目标是查看调用java.net.SocketInputStream的构造器调用的堆栈信息。植入后顺利发现了以下调用链路很频繁：

thread=["0x6c", "commons-pool-EvictionTimer"] 
java.net.SocketInputStream.<init>(SocketInputStream.java:61) 
    at java.net.AbstractPlainSocketImpl.getInputStream(AbstractPlainSocketImpl.java:425) 
    at java.net.Socket$2.run(Socket.java:914) 
    at java.net.Socket$2.run(Socket.java:912) 
    at java.security.AccessController.doPrivileged(AccessController.java:-2) 
    at java.net.Socket.getInputStream(Socket.java:911) 
    at redis.clients.jedis.Connection.connect(Connection.java:204) 
    at redis.clients.jedis.BinaryClient.connect(BinaryClient.java:93) 
    at redis.clients.jedis.BinaryJedis.connect(BinaryJedis.java:1767) 
    at redis.clients.jedis.JedisFactory.makeObject(JedisFactory.java:106) 
    at org.apache.commons.pool2.impl.GenericObjectPool.create(GenericObjectPool.java:868) 
    at org.apache.commons.pool2.impl.GenericObjectPool.ensureIdle(GenericObjectPool.java:927) 
    at org.apache.commons.pool2.impl.GenericObjectPool.ensureMinIdle(GenericObjectPool.java:906) 
    at org.apache.commons.pool2.impl.BaseGenericObjectPool$Evictor.run(BaseGenericObjectPool.java:1046) 
    at java.util.TimerThread.mainLoop(Timer.java:555) 
    at java.util.TimerThread.run(Timer.java:505)

这里能很清楚的看到是jedis底层的commons-pool负责创建的。

STEP2

追溯到这一行：

org.apache.commons.pool2.impl.GenericObjectPool.ensureIdle 

我们想要看下为什么commons-pool需要不停创建新的socket连接。在我们使用的2.4.2版本下源码如下：

我们可以很清楚的看到，当空闲对象池(idleObjects)大小不够时，会去调用create方法创建新的连接，即和jedis服务器生成了新的socket对象。

现在的问题变成了，为什么空闲池会不够？按理说当 redis 调用使用完成后会立刻returnObject到对象池。于是尝试在对象池的各个环节如borrow, return, destory都打上了埋点，果然发现了一些信息。

STEP3

在JedisPoolConfig中有如下的配置：

setTimeBetweenEvictionRunsMillis(30000); 

这个参数的含义是每30秒钟执行一次空闲对象驱逐。什么是对象驱逐? 这是commons-pool对象池的一种对象更新机制。意思是我会定期清理一下对象池中的数据, 保证数据对象在某种程度上是“新”的。具体的操作在

org.apache.commons.pool2.impl.GenericObjectPool#evict 

evict = evictionPolicy.evict(evictionConfig, underTest, idleObjects.size()); 

再进一步可见 org.apache.commons.pool2.impl.DefaultEvictionPolicy#evict

这里是对象池执行驱逐的默认策略。简单来说就是：

• 如果空闲时间超过1分钟，但是池子里的总idle数量大于了minIdle，那么我可以驱逐你；

• 如果你已经空闲了超过30分钟，我一样可以干掉你。

这样jedis的连接对象就会一直不停的被驱逐，然后再创建。这也充分解释了STEP1和STEP2。

STEP4

回到问题本身。既然对象被驱逐了，对象池始终保持在配置的范围内，那么为什么这么多的Socket还是泄露了(无法被及时GC)？

注意看最开始的jmap的截图有这么一行：

11: 277960 11118400 java.lang.ref.Finalizer 

看到这里需要注意：

• Finalizer对象的数量和Socket对象泄露的数量相当。

• 大量的Finalizer说明有对象实现了finalize方法且在回收队列中，而且这里很可能是socket某个类实现了finalize方法。

检查发现：

java.net.AbstractPlainSocketImpl#finalize 

protected void finalize() throws IOException { close(); } 

官方注释也说的很明白 【Cleans up if the user forgets to close it.】。也算是为了用户考虑了(假如用户没有关闭socket, 在回收前jvm会帮你努力一把)。

但是结合 STEP0 的GC, 我们也很容易得出如下结论：

• 该机器的定时任务本身会导致YGC相对其他机器较为频繁。

• commons-pool的驱逐机制导致会不停的创建Socket相关对象。 加剧YGC的频次。

• 但是Socket对象实现了finalize方法,导致所有对象会进入f队列, 使的被回收的时间延长。 所以Socket对象都要依次在队列中执行finalize。

• finalize队列执行速度追不上对象池的驱逐速度。 驱逐的越快, 则内存泄露越加剧。

• jedis的minIdle配置的太大, 我们配置了150。 所以很多时候很容易驱逐结束后空闲数量小于150。 然后就不停的创建Socket。

总结

不要忽视任何微小的问题。

作者简介

盈超，2018年加入网易严选，目前参与严选库存中心以及库存周边的数据开发工作。曾在淘宝负责卖家中心，用户开店，商品心选等业务。对于JVM以及系统的疑难杂症有浓厚兴趣。

本文由作者授权严选技术团队发布