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以及系统的疑难杂症有浓厚兴趣。
本文由作者授权严选技术团队发布
正文到此结束
热门推荐
相关文章
近期评论
-
666
-
文章和留言都翻到11页了 没有OOM
-
-
朋友，翻页到11页，及以后，会出现OOM，无法访问
-
-
-
-
版本号是多少，你可以下载哪个代码仓库，jdk选1.8 直接跑就行
-
-
Loading...
![[HBLOG]公众号](https://www.liuhaihua.cn/img/qrcode_gzh.jpg)
