性能文章>慌了!LinkedHashMap和hashTable的Entry居然有500w之多,还无法回收>

慌了!LinkedHashMap和hashTable的Entry居然有500w之多,还无法回收原创

7637213

故障介绍

某一日早上七点,我还在睡梦之中,8点醒来发现运维群内有人at。一看说是用户服务的一个节点挂掉了。然后大概原因是因为OOM,运维还在群里发了一个jstack 的栈dump文件,未必是事故发生时的dump文件。oom.hprof文件太大,只能去公司看了。

image.png

初步排查

去公司以后就下载了gc.log。发现在应用宕机的时候,有过两次full gc。结合运维的描述,确实当时程序停顿了两次,每次停顿都将尽3~4秒,通过业务日志发现,那时候的dubbo调用是超时的。

另外一个发现就是,我通过gc.log发现,在gc时,内存是被成功回收的。但是回收率不高。

image.png

下载oom.hprof。打开看看吧。一打开就吓死了:LinkedHashMap的Entry和hashTable的Entry居然有500w之多,无法回收。而且里面基本上都是String类型的key/value。

image.png

让我们揭开600w的string的key/value。发现:和RSA加解密相关,都是一些算法类路径和算法类型。

image.png

直觉告诉我,应该是程序里RSA的加解密工具类误用造成的内存泄漏吧?于是定位到RSAUtil里一段加密的代码:

image.png

发现每次加解密都会调用一次Secturity.addProvider函数,在这个函数里,每次都new一个BouncyCastlePrivider();

image.png

发现BouncyCastleProvider()里一顿put:

image.png

我debug了一下Sectury.AddProvider();发现BouncyCastlePrivider这个对象继承自HashTable。每new一个BouncyCastlePrivider,能直接看到相当于new了size为2615的map。惊呆了。

image.png

于是认为这就是一个简单的内存泄漏问题。打算写一段代码复现:不断的加解密,看一下内存变化情况。

image.png

发现eden区的内存会缓慢飙升,但是执行gc的时候,是可以被回收的啊。。

说好的内存泄漏呢?看起来,虽然我们这里每次都new BouncyCastlePrivider() 肯定是误用了。但是并不会直接造成内存oom啊。因为new 出来的BouncyCastlePrivider() 在失去他的作用域以后,在堆区满了以后,发现确实是能够回收的,没道理造成内存OOM。

image.png

定位问题

中午吃饭的时候和运维进行了交流,获取了一些更加有用的情报:

  1. 只有1台机器发生了oom。

  2. 发生oom的时候这服务的活跃线程数增多。

活跃线程数增多是因为并发造成的?不是,因为请求是平均路由的。其他实例的活跃线程数并不多,单独这台机器活跃线程数多。而线程处于wailt状态,time_wailt状态,是非活跃线程,而线程处于runnable状态和blocked状态,是属于活跃线程。

于是打开了oom文件,去分析线程情况。发现我们用的dubbo框架的2000个业务线程都被blocked了。这就能解释为什么当时活跃线程数增多了,因为du bbo的业务线程被blocked了,新来的请求使用空闲线程执行业务逻辑,然后也被bolcked了。最后2000个线程大部分都是bolcked状态。从监控面板上看,属于活跃线程数突然增多了。

image.png

结合上午排查的内存情况来看。我初步估计,是因为2000个业务线程大部分都是bolcked状态,且应该bolcked源在加解密工具类里面,这时候,2000个线程都持有着BouncyCastlePrivider这个对象的栈上的引用,gc是无法清理存活着的对象的占用内存的,于是只好OOM。

上边分析HashTable的entry引用个数为5430169。而每new一个BouncyCastlePrivider对象,上面debug,map.zise 为2651。即是2615个Entry对象。5430169 / 2651 = 2048个线程,5430169个hashentry对象不一定全都是BouncyCastlePrivider对象持有的,应该减去1~2w的entry,是其他对象正常持有的。通过初步估算发现,OOM和map.size 和dubbo的线程池总线程数,是基本能对得上的。

那就review一下BouncyCastlePrivider的构造函数代码吧?到底干了些啥?

image.png

review以后发现在loadPQkeys函数里,调用了7次addKeyInfoConverter函数。而这个函数,加的锁是一个静态锁!

image.png

image.png

也就是说,多个线程执行BouncyCastlePrivider的构造函数,会竞争7次静态锁,造成线程被blocked 。那写段代码复现一下。这段代码表示500个线程同时发起加密,加密以后500个线程同时发起下一轮加密。

image.png

打印实时堆栈:

image.png

分析jstack日志。发现确实很多线程在BouncyCastlePrivider内部被blocked。bolcked入口是loadAlgorithms函数。

image.png

image.png

追到底层,原来是因为BouncyCastlePrivider每次构造函数调用都会重复加载8个类。而类加载器里面加载一个类,会根据类名称进行加锁。相同的类在加载时互相等待锁,而从jar包加载一个类本身就是比较耗时的。因此造成线程被blocked。

image.png

其他疑问:

  1. 为什么这个加解密算法的使用早就有问题了,为什么现在才爆出来?

实际上是因为业务逻辑已知的修改,造成了加解密函数的被调用次数增多了。之前没出现问题是因为调用次数少,而且这个问题并不是死锁问题,仅仅是竞争多了会造成bolcked而已。

  1. 为什么这个服务多个实例,只有一台机器有问题呢?

暂时原因不明,可能是那台机器性能本身就开始有问题,从而诱发了线程执行耗时慢,而搭配我发现的这个代码问题,雪上加霜,从而造成了OOM。

结论

本次故障的原因,表面看上去是内存泄漏。实际上是因为大量线程bolcked导致的引用的内存不能即使释放 + 误用BouncyCastlePrivider对象,生成大量重复对象造成了无用内存占用 同时发生造成的OOM。

经验教训1:在使用别人家的类库的时候,我们一定要搞清楚这个对象是有状态的,还是无状态的,是很重,应该实例化一次,还是每次都要实例化。

经验教训2:不能网上粘的代码就随便乱用。实际上很多网站别人公开的代码都是有很多坑的。应该养成能分析网上的代码合理不合理的能力。这次加解密函数的故障,就是因为之前这些代码都是网上直接拷贝的。

本文来自公众号:chen陈序猿

请先登录,查看2条精彩评论吧
快去登录吧,你将获得
  • 浏览更多精彩评论
  • 和开发者讨论交流,共同进步

为你推荐

字符串字面量长度是有限制的
前言 偶然在一次单元测试中写了一个非常长的字符串字面量。 正文 在一次单元测试中,我写了一个很长的字符串字面量,大概10万个字符左右,编译时,编译器给出了异常告警 `java: constant
多次字符串相加一定要用StringBuilder而不用-吗?
今天在写一个读取Java class File并进行分析的Demo时,偶然发现了下面这个场景(基于oracle jdk 1.8.0_144): ``` package test; public c
如何通过反射获得方法的真实参数名(以及扩展研究)
前段时间,在做一个小的工程时,遇到了需要通过反射获得方法真实参数名的场景,在这里我遇到了一些小小的问题,后来在部门老大的指导下,我解决了这个问题。通过解决这个问题,附带着我了解到了很多新的知识,我觉得
高吞吐、低延迟 Java 应用的 GC 优化实践
本篇原文作者是 LinkedIn 的 Swapnil Ghike,这篇文章讲述了 LinkedIn 的 Feed 产品的 GC 优化过程,虽然文章写作于 April 8, 2014,但其中的很多内容和
「每日五分钟,玩转 JVM」:久识你名,初居我心
聊聊 JVMJVM,一个熟悉又陌生的名词,从认识Java的第一天起,我们就会听到这个名字,在参加工作的前一两年,面试的时候还会经常被问到JDK,JRE,JVM这三者的区别。JVM可以说和我们是老朋友了
据说99.99%的人都会答错的类加载的问题
概述首先还是把问题抛给大家,这个问题也是我厂同学在做一个性能分析产品的时候碰到的一个问题。 同一个类加载器对象是否可以加载同一个类文件多次并且得到多个Class对象而都可以被java层使用吗请仔细注意
Java多线程——并发测试
编写并发程序时候,可以采取和串行程序相同的编程方式。唯一的难点在于,并发程序存在不确定性,这种不确定性会令程序出错的地方远比串行程序多,出现的方式也没有固定规则。那么如何在测试中,尽可能的暴露出这些问
Java多线程知识小抄集(一)
本文主要整理笔者遇到的Java多线程的相关知识点,适合速记,故命名为“小抄集”。本文没有特别重点,每一项针对一个多线程知识做一个概要性总结,也有一些会带一点例子,习题方便理解和记忆。 1.interr