一、问题描述
前阵子我们因为B机房故障,将所有的流量切到了A机房,在经历了推送+自然高峰之后,A机房所有服务器都出现java线程数接近1000的情况(1000是设置的max值),在晚上7点多观察,java线程数略有下降,但还是有900+的样子,而此时,单台服务器的TPS维持在400/s,并不是一个特别大的量。然后将A机房一台机器下线,继续观察,到了晚上9点多,那台下线的机器,jetty进程的java线程数还是7、800的样子。同时,同一机房的另外一台还在线的机器在重启jetty之后,在同样tps400+的情况,线程数一直保持在只有300多。这就很奇怪了,下线的机器都没有请求了,java线程数怎么还是这么多?会不会是多线程竞争资源,导致阻塞?开始研究这个问题。
二、保存现场
保存哪些现场
我先查看并记录了当时的jetty进程的线程数、db连接数、cpu负载、内存使用情况、tps、
nginx连接数、jetty错误日志、GC情况、tcp连接状态等,都是正常。
然后我用jstack命令导出当前jvm的所有线程快照,用jmap命令将当前java堆转储快照导出,结果发现,除了java线程数之外,其他指标也都是正常。
这里先说下jstack和jmap使用的常用参数举例和注意事项:
找到jetty进程pid
对于这两个命令,首先都需要找出jetty进程对应的pid,当然可以使用jps命令来查找对应的pid。
但是,我当前linux用户是自己的用户名用户,而公司外网服务器我并没有jetty的权限,也就是说jps命令只有jetty用户可以查看。
在网上找了下资料,这里我采用的是这种方式,用ps aux|grep jetty.xml找到了jetty进程对应的pid。
jstack保存线程快照
我使用jstack完整命令是:“sudo -u jetty /data/java/bin/jstack -l pid >> ~/jstack.txt”。-l 参数是将锁的信息也打印出来。
这里,有个比较隐蔽的坑,我们的jetty进程是jetty用户的。如果在linux上是root用户或者其他用户直接执行jstack -l pid,会出现报错。所以,需要在命令前加上sudo -u jetty,用jetty账户来执行这个命令。
而jetty账户又不一定将/data/java/bin加入环境变量,所以需要执行jstack的完整路径。
执行完毕的结果存放在home目录下的jstack.txt文件中。(这里是找运维同事协助完成的)
jmap保存堆转储快照
同样,jmap命令也需要注意命令执行的用户。我使用的完整命令是:“sudo -u jetty /data/java/bin/jmap -dump:format=b,file=~/jmap.hprof pid”。
导出来的hprof文件非常大,保存了当时堆中对象的快照。hprof不能直接阅读,需要用专门的工具来分析。最常用的是mat和jhat。mat是图形界面的工具,有windows版的,比较方便。但是mat有个死穴,当分析的hprof文件过大时,会出现内存溢出的错误而导致无法得到结果。我曾经尝试解决这个问题,但是一直没有找到有效的方法。所以这里我用的是jhat。
jhat分析堆转储快照
jhat是java自带的命令行工具,比较简朴。但是对于特别大的文件,好像是唯一的选择。将hprof文件压缩,下载到开发环境的虚拟机上,就可以开始用jhat分析了。
我使用的完整命令是:“jhat -J-d64 -J-mx9g -port 5000 jmap.hprof”。来解释一下参数。-J-d64:因为jetty进程是在64位的系统上运行,所以需要指定64位。-J-mx9g:表示jhat进程最多可以分配9G的堆内存,这就是为什么jhat可以分析超大文件的原因了,因为可以指定堆内存大小。-port 5000:jhat分析完毕之后,会启动一个web服务,可以通过指定端口来访问,这就是指定的端口。
参数就介绍完了,但是这样的命令会有一个问题。上面的命令执行完,jhat进程是在前台的。换句话说,如果你ctrl+c(或者xshell连接超时)结束了这个前台进程,那么jhat提供的web服务就结束了,你刚才分析了那么久的文件得重新再来。解决这个问题,用到linux上的nohup和&组合。通过命令“nohup jhat -J-d64 -J-mx9g -port 5000 jmap.hprof &”,就可以将进程放到后台执行。有兴趣可以研究一下nohup,在这里不做赘述。
jhat分析需要一定时间。可以用top命令看,当jhat进程没有疯狂的吃cpu的时候,说明分析已经结束了。此时,可以通过ip:port来访问刚才分析出的结果了。
三、定位问题
首先,来看刚才的jstack.txt。
在近900个线程里面,有600+个线程都是wait在同一个对象<0x0000000734afba50>上,而且这600+个线程的调用栈都是一模一样的。去查了一下,这个org.eclipse.jetty.util.thread.QueuedThreadPool的作用,就是jetty的worker线程池。每当一个请求来临的时候,jetty就从这个QueuedThreadPool中新建一个线程或者取一个空闲线程来处理这个请求。
看到调用栈里面的“at org.eclipse.jetty.util.thread.QueuedThreadPool.idleJobPoll(QueuedThreadPool.java:526)”,感觉好像这些线程都在等待任务来处理。当然,这是猜的。
为了验证这个猜想,找到刚才jhat已经分析好的堆的快照结果。首先,我找到“class org.eclipse.jetty.util.thread.QueuedThreadPool”这个类,然后依次点击,进入到QueuedThreadPool的唯一的实例中。
到这里,就可以看到QueuedThreadPool这个对象中所有成员变量了:
其中,有两个AtomicInteger型变量在这里需要关心:_threadsStarted和_threadsIdle。
_threadsStarted表示QueuedThreadPool当前拥有的线程数,而_threadsIdle表示QueuedThreadPool中空闲的线程数。
点击进去,就看到这两个成员变量的值,value分别是707和613。
这表示,QueuedThreadPool当前开启了707个用于处理用户请求的线程,而其中有613个处于闲置状态。
到这里,我们上面的猜想基本得到验证。那些大量的time_wait的线程,真的是处在等待请求到来的状态。那么问题是,既然是闲置的线程,为什么jetty没有进行回收,time_wait有这么长时间吗?
四、分析jetty源码,确定原因
要继续确定为什么空闲线程没有被回收原因,分析jetty源码是一种思路。我只找到和线上jetty大版本一样,小版本接近的jetty源码。但是不妨碍理清这部分的逻辑。
继续回到刚才的jstack的结果中:
熟悉阻塞队列的人都知道,栈中的“org.eclipse.jetty.util.BlockingArrayQueue.poll(BlockingArrayQueue.java:342)”,就是从一个指定的阻塞队列中去获取任务。如果此时阻塞队列中没有任务可取,线程就会被阻塞住,直到队列中有任务可取或者超时。如果超时,poll方法将返回null值。进入到idleJobPoll()方法中,也很容易就发现,poll的超时时间也是用了刚才的_maxIdleTimeMs变量,也就是60s。所以才会发生600+个线程同时wait一个条件的情况。这些线程都在等待BlockingArrayQueue中任务来临这个Condition。那么,是谁让线程调用poll的?为什么poll设置了超时时间,在超时之后,线程没有结束呢?为什么这些空闲线程没有被及时回收呢?
带着这些问题,我们来看QueuedThreadPool的源码。我们直接找到调用了idelJobPoll()方法的这块代码,如下:
这里有几个变量和方法需要先说明一下。_maxIdelTimeMs是QueuedThreadPool中的一个成员变量,表示超时的毫秒数,默认值是60000(表示60秒),可以在刚才jhat分析的结果中查询到这个值。_lastShrink也是QueuedThreadPool的一个成员变量,是线程安全的AtomicLong类型,表示上一次线程退出时的
时间戳,被所有线程池中的线程共享。campareAndSet方法,就是著名的CAS(比较后赋值)。例如:_lastShrink.compareAndSet(last,now)的意思是,先将_lastShrink和last比较看是否相同,相同则将_lastShrink的值等于now并返回true,否则不进行赋值并返回false。
当一个空闲线程从idelJobPool()方法中超时后获取到null值,会再次进入while循环。此时的线程数size(700+)是要大于_minThreads(设置的为200),所以会进入框中的if代码块。if代码块中主要经历了以下步骤:
1.将last赋值为上一个线程池中的线程退出时的时间戳,将当前时间赋值给now。
2.然后“if (last==0 || (now-last)>_maxIdleTimeMs)”这一句判断,now距离上一个线程退出是否超过了maxIdleTimeMs(60000,60秒)。
3.如果2步骤中条件成立,会对_lastShrink重新赋值为当前时间,并将QueuedThreadPool中的线程计数减一。
campareAndSet保证了,每一次只会有一个线程能够赋值成功。
赋值成功后,就会return,让线程跳出while循环,这个线程就结束了。
对于赋值不成功的线程,会继续执行到idleJobPoll(),和步骤4相似。
4.如果2步骤中条件不成立,会重新回到idleJobPoll(),阻塞住线程,又会尝试从阻塞队列中获取任务。
也就是说,每当一个空闲线程执行到框中的代码时,都要判断现在距离上次有线程退出是否超过60s。如果没有超过60s,这个线程会继续回到idelJobPool方法中去等待任务。换句话说,1分钟之内,QueuedThreadPool最多只能允许一个线程退出。那么,我们600+个空闲线程如果要全部退出,那就要600分钟,也就是10个小时!!
难怪,会有那么多空闲线程在那里啊,虽然这些空闲线程可以被重复利用并不影响业务,但也是占用了线程资源。不知道这个算不算是个bug,但是真的很坑。由其影响通过java线程数去判断业务的繁忙情况,容易受到误导。
五、实验验证
为了进一步验证这个结论,我在开发环境部署了一样的业务,纯净且没有其他人访问。用ab以1000并发量发起30000个请求,迅速将java线程数提升至1000(最大值)。然后用watch命令,每5分钟观察一次java线程数,下面是部分结果:
可以看到,每5分钟,线程数都下降了5。确实是1分钟退出一个线程啊!
六、结论
这整个过程最重要的结论就是,当发现java线程数非常高的时候,不必太担心。有可能只是jetty没有及时回收空闲线程而已。更重要的是,要掌握分析的工具和方法,查找出现象背后的原因。