事件经过:
上周一,运维突然发现生产环境有一台机器出现了大量线程在执行同一操作,检查发现是卡在了我写的一个接口里。jstack发现所有线程都在执行HashMap的get()方法上卡住了,最多的已经执行了上千秒。因为生产环境用的是JDK1.7,领导一看就判断出了原因:有多线程对HashMap进行put操作时触发HashMap扩容,因为并发扩容造成某个链表成环,后来的线程在这个Map上进行get操作时在链表上进入了死循环。因为这个接口是我写的,于是当即找到我,要我找到出问题的代码并修复。
关于JDK1.7下多线程修改HashMap造成死循环的问题,网上一大把,比如这篇:老生常谈,HashMap的死循环
我虽然是个财年,但还是知道HashMap是不能在多线程环境下使用的,记忆中这个接口也没有任何成员变量使用了HashMap,多线程修改HashMap的情况是怎么出现的?抱着疑问我开始了排查。
我所在的部门是某手机银行APP的后台,出问题这个接口功能是给APP某个理财产品推荐的组件下发数据(后面就记为A接口),接口逻辑是这样的:
从直销系统获取一款主推产品,这款产品所有客户都是一样的,但是隔一段时间就会更换,记为①
从大数据推荐中台获取数款产品,数量不定,这些产品会针对不同客户做差异化推荐,记为②
为了防止大数据推荐的产品因售空等原因无法购买,接口在拿到推荐产品后还会根据一定的规则做校验,过滤掉不合格的产品;又为了防止②被过滤后产品数量不足,保证至少返回给客户端3款产品,又准备了几款默认产品,以补足3款的数量,这些补位的产品没有特殊原因不会更改,但是可以通过后管修改,记为③
因为框架要求返回的数据必须是List、Map格式,为了避免返回数据前的转换,所以我也偷懒把产品的数据都用HashMap存放(这也是本次线上BUG的原因之一,如果我用javaBean存放数据,虽然最后在return前要转换一次,但也不会出现这个BUG了),每一个HashMap就是一款产品。所以接口返回的数据是List<Map>
这样的格式。
整个接口的逻辑写成伪代码大概是下面这样:
public List<Map> getRecommends(String custId) {
......
List<Map> recommends = new ArrayList<>();
List<Map> fromBigData = getBigDataRecommends(userId); // 1 大数据推荐的产品
Map directSelling = getDirectSellingFromCache(); // 2 从缓存拿到的直销产品
List<Map> defaultProducts = getDefaultFromCache(); // 3 从缓存拿到的补位的默认产品
recommends.add(directSelling); // 直销的产品要求放第一位
recommends.addAll(fromBigData);
recommends.addAll(defaultProducts);
recommends = dedumplicateAndGetFirstN(recommends, 3); // 去重并取前3款产品
......
return Recommends;
}
①是请求接口拿到的,因为②③的内容是所有客户都一样的,也不经常变化,所以②③是从缓存拿到的,缓存里的内容由一个后台线程定时刷新。
发生死循环的代码就在dedumplicateAndGetFirstN
这个方法里面,所以我判断出问题的代码应该在①②③3个方法上。事实证明这是我犯的又一个错误。
因为生产上没有开启heap dump,看不到线程进入死循环时Map里的内容,也就无法通过查看数据的方式快速判断是上述①②③中哪里出了问题。
我只好采用笨办法,三个方法相关的所有代码都看了两遍,并没有发现哪个地方有可能造成多线程对HashMap的操作,也没有发现HashMap被赋值给成员变量之类的情况出现。为了防止自己看自己的代码陷入思维上的死胡同,我又请了一位同事帮忙查看,可是她也没有看出有什么问题。看代码,跟同事讲其中的逻辑就花了个把小时,仍然毫无头绪。
一筹莫展之际,只能求助领导。领导是位很有经验的大神,他并没有一上来就检查①②③的方法,而是问我,我有没有对从缓存取出来的数据做什么操作。
这里要先说明一下,②③两类产品拿数据的缓存并不是redis之类的持久化数据库缓存,而是业务团队自己写的K-V缓存工具类,内部实现是ConcurrentHashMap,从缓存拿到的数据,实际上就是放入缓存的那个对象的引用。所以如果某个线程拿到缓存中的某条数据并修改了其中的内容,那么别的线程从缓存中拿到的就是修改后的内容。我是知道这一点的,所以我更新缓存的方式是用后台线程定时更新缓存内容,业务线程只负责从缓存中取数据。
领导没有跟我多废话,而是把代码往后翻了翻,问题找到了。前面伪代码打省略号的部分有个叫做addDisplayStyle()
的方法:
public List<Map> getRecommends(String custId) {
......
List<Map> recommends = new ArrayList<>();
List<Map> fromBigData = getBigDataRecommends(userId); // 1 大数据推荐的产品
Map directSelling = getDirectSellingFromCache(); // 2 从缓存拿到的直销产品
List<Map> defaultProducts = getDefaultFromCache(); // 3 从缓存拿到的补位的默认产品
recommends.add(directSelling); // 直销的产品要求放第一位
recommends.addAll(fromBigData);
recommends.addAll(defaultProducts);
recommends = dedumplicateAndGetFirstN(recommends, 3); // 去重并取前3款产品
......
recommends = addDisplayStyle(recommends);
......
return Recommends;
}
// 在数据返回前,给所有产品加上一个displayStyle字段
private List<Map> addDisplayStyle(List<Map> reommends) {
for (Map product : recommends) {
String displayStyle = "";
if (xxx) {
displayStyle = "valueA";
} else {
displayStyle = "valueB";
}
product.put("displayStyle", displayStyle);
}
}
问题就出在这个addDisplayStyle()
方法身上,这个方法的入参reommends里面,已经包含了从缓存中取出的直销产品和补位的默认产品,在有多个APP请求A接口的情况下,业务线程执行到product.put("displayStyle", displayStyle);
这行代码时,实际上就是在往同一个Map中put元素,并且由于key一样,等于一定会发生哈希冲突,只要刚好这时某个Map的元素个数达到了扩容条件,就会触发扩容,并有概率发生链表成环的现象。当再有请求到来,工作线程执行到前面的
recommends = dedumplicateAndGetFirstN(recommends, 3);
这行代码时,就发生了死循环。
这时我也想起了我增加这个方法的原因:这个接口是某次客户端大版本更新时由我重构的接口,这个"displayStyle"字段是很久以前的老版本客户端所使用的,但是这些老版本客户端已经全部下线,这个字段已经不需要了,所以在新版接口中是计划要删掉的,我重构的代码中也已经把这个字段去掉了,①②③返回的Map中都没有这个字段。然而在测试到中途的时候,ios客户端发现一些仍然在线的老板客户端因为某些原因仍然在使用这个字段,如果返回数据中如果没有这个字段客户端会造成展示错误,因此要求我把这个"displayStyle"加上。我只好重新修改已经提测的代码,不过为了省事,我的做法不是分别修改①②③的3个方法,而是直接在A方法返回数据前加上了addDisplayStyle()
这个方法,完全忽略了②③的数据是来自缓存这个事实。由于测试环境并发量不够,死循环问题几乎无法复现,只有上到生产之后,并发量高起来,才有可能触发这个BUG(实际上这个代码已经上线半年了,直到这次才第出现问题)。
总结:
本来文章标题想叫《记一次因错用HashMap造成的生产BUG》的,但感觉“错用HashMap”这标题像足了某些java公众号写的标题党文章,所以还是改成现在这个了。虽然在A接口里把所有产品都放到HashMap里是不太正规,但在实现上是可行的,所以并不是“错用”。一个合格的Java程序员都必须知道HashMap是不能在多线程环境下使用的,我在写代码的时候也都尽量地遵守这个要求,不过还是因为疏忽大意,忽略了缓存这个问题,仍然写出了有BUG的代码。
这次的线上BUG又教会了我这个菜鸟几件事:
1、使用这种直接存放对象引用的内存缓存,在存放内容可变的对象的时候,一定要注意不要修改从缓存中获取的内容
2、修改代码时一定要通盘考虑,结合前面和后面的逻辑,思考清楚这样修改的后果。像这次BUG,正是因为所有的代码都是我自己写的,所以在增加addDisplayStyle()
方法时才会麻痹大意,想着“就是加个字段而已”,如果是修改别人的代码,我至少会先检查一下前面的逻辑,思考一下数据是怎么来的,那么这个并发修改HashMap的问题其实很容易就能发现。
3、找bug时思维不要陷入死胡同,代码在第10行运行异常,那么问题不一定出在前9行,本次事件就是一个例子。
4、遇到问题自己解决不了的时候,会抱大腿很重要,领导过来,几分钟就发现了我个把小时也没找到的BUG,不然还不知道陷入思维误区的我还要在这事上折腾多久呢。这也是这次我唯一做对的意见事吧……