一次线上java应用响应时间过长问题的排查

最近接手一个老java应用,没多久接到响应时间太长的报警,整个排查过程还是挺有意思的,记录一下。
整个过程中,设计到cpu,内存,垃圾回收,引用,spring, 单例 等等知识,整个下来,心情愉悦。

接到报警

吃完晚饭回来,接到报警短信,服务响应时间太长,达到2s以上。
第一反应,怎么可能,这个应用很简单,就提供了几个查询接口,QPS单机也就10左右,居然响应时间2s以上,这不科学。

看监控

看监控平台,有问题的机器,cpu占用很高,这。。。更不科学了。理论上,这应用cpu能到1%就不错了,现在居然80%,吓得我赶紧跑到机器上,top了一把,确实是java应用占用cpu很高。

找出占用cpu的线程

ps -mp pid -o THREAD,tid,time

发现cpu几乎全被一个线程占用了,将线程id转换成16进制

printf "%x\n" tid

打印线程堆栈信息

jstack pid |grep tid -A 30

看到的结果居然是,CMS垃圾收集器的线程。。。
这,这,这不科学。

垃圾回收

看垃圾回收日志,发现一直在进行Full GC,但是几乎没啥效果,GC完了,老年代依然是几乎占满的状态。
即使是CMS,也不能避免传说中的stop the world,所以响应时间变长了。
但是,现在问题来了,Full GC回收不掉的对象都是啥啥啥?

分析java堆内存

先把线上流量从这台机器切走,然后dump,分析后发现,一共160多万个PoolHttpConnectionManager对象占领了绝大多数内存。
会议了一下代码,和http请求有关的只有oss存储的client了。
猜测是new oss client时的问题

oss client 源码

看了一下应用中的代码,发现每次使用oss时都会 new OssClient,用完之后没有shutdown。
但是,new是在方法内部的,方法内的局部变量按道理说,方法结束后直接就可以回收的啊,这不科学,肯定是ossClient的源码中搞了鬼。于是直接去源码中看了一下。
发现在new OssClient时,源码中会新建上面提到的PoolHttpConnectionManager,然后调用ossClient存取数据时,PoolHttpConnectionManager会从内部维护的http连接池中找到可用连接,进行操作。
这没问题,大多是框架都是这么设计的。
既然JVM 堆内存中有160多万个PoolHttpConnectionManager对象,说明肯定是有地方把内次new OssClient时新建的PoolHttpConnectionManager给缓存起来了,导致垃圾回收无能为力。
继续看源码,发现确实和我想的一样。给存起来了,只有显式调用ossClient的shutdown,才会清理掉缓存。
想想这样设计也没问题,这和线程池的思想是一样的,我们使用线程池时,肯定不会每次都new 一个新的,只不过这个ossClient隐藏的比较深。。。

解决

解决办法很简单,把OssClient改成单例就行了。
但是,集团封网期间不允许上线,这。。。
没办法,把应用重启一遍,JVM内存满血复活,清醒QPS很低,重启后可以撑过封网的时间断了

Spring的Controller是单例的

突然想到,其他应用也使用了这个OssClient,一直没问题,想必是单例吧,忍不住上去瞅了瞅代码,发现,是在一个Controller中使用了成员变量,像这样:

@RestController
@RequestMapping("/hello/world")
public class MyController {
    private OSSClient ossClient = new OSSClient();

    public put(Object o) {
	ossClient.put(0);
    }

我记得上学那会儿,捣腾Struts的时候,Action并不是单例的啊,单里会有问题,难道Spring是单例了?
查了一下,确实,Spring的Controller,默认是单例。
想了想,单例也没啥问题,只要不在方法中去操作成员变量就可以了。

后记

你所学的知识,都是有用的,认为没用,也许只是时候未到而已。


因僧问我西来意,我话山居不记年。
草履只栽三个耳,麻衣曾补两番肩。
东庵每见西庵雪,下涧常流上涧泉 。
半夜白云消散后,一轮明月到床前。