今天在新环境里部署tomcat, 刚开始启动很快,关闭之后再启动,却发现启动日志打印到
00:25:14.144 [localhost-startStop-1] INFO o.s.web.context.ContextLoader - Root WebApplicationContext: initialization completed in 6287 ms
一直hold着,tomcat程序也无法访问,以为是程序哪里配置错了,找了半天,甚至把spring的配置加载完全去掉才能启动,why, 程序在开发环境可是刷刷刷就跑起来的
后来一直没管这程序过了几分钟去看日志,发现tomcat 程序才启动完毕,why?原来不是卡住,而是慢
用jstack 观察一下启动线程, 发现 C2 CompilerThread 占用cpu很高, 同时 org.apache.catalina.util.SessionIdGeneratorBase.createSecureRandom这里读文件也产生阻塞,占用CPU也很高。
一、问题描述
在发布或重启某线上某服务时(jetty8作为服务器),常常发现有些机器的load会飙到非常高(高达70),并持续较长一段时间(5分钟)后回落(图1),与此同时响应时间曲线(图2)也与load曲线一致。注:load飙高的初始时刻是应用服务端口打开,流量打入时(load)。
图1 发布时候load飙高
图2 发布时候响应时间飙高
二、问题排查方法发布时对资源使用情况进行监控。
1)通过top -H -p 查找cpu使用率较高的线程,发现2129和2130这两个线程cpu使用较高。
图3 查找cpu使用率较高的线程
2)通过jstack打印栈信息,并将线程号2129和2130转换成16进制(printf "%x\n" 2129),分别为851和852,发现这两个线程是编译线程(表1)。此外当这两个线程cpu使用率降低后load以及响应时间也马上恢复了正常,时间点非常吻合。
表1 cpu使用率较高的两个线程详细信息
"C2 CompilerThread1" daemon prio=10 tid=0x00007fce48125800 nid=0x852 waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
Locked ownable synchronizers:
- None
"C2 CompilerThread0" daemon prio=10 tid=0x00007fce48123000 nid=0x851 waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
Locked ownable synchronizers:
- None
C2 CompilerThread线程项目启动初期cpu使用率那么高,它在干什么呢?
Java程序在启动的时候所有代码的执行都处于解释执行模式,只有在运行了一段时间后,根据代码方法执行的次数,或代码里循环的执行次数等达到一定的阈值才会编译成机器码,编译成机器码后执行效率会得到大幅提升,而随着执行时间进一步拉长,JVM的各种更高级的编译优化手段就会逐渐加上,例如if条件的执行状况,逃逸分析等。这里的C2 CompilerThread线程干的就是编译优化的活。
现在貌似可以解释之前的现象了。
在程序刚启动的时候,java还处于解释执行模式,因此服务效率很低,响应时间缓慢,处理得慢了,load自然也就高了。而当流量持续不断导入时,我们代码的很多方法执行次数不断增多,此时C2 CompilerThread线程不断收集优化信息,并且开始将一些热点代码优化编译成本地机器码,因此该线程的cpu使用率增高。而当C2 CompilerThread线程完成初始编译优化过程后,C2 CompilerThread线程的cpu使用率开始下降,与此同时优化后服务的性能大幅提升,服务响应时间也大大缩短,load也下降。
现在的症结在于编译优化过程持续时间较长,引起抖动。如何降低编译优化的持续时间呢?
四、解决思路 1)预热如果在服务接受线上请求之前提前完成编译优化过程,那么将能避免此种抖动情况。一般的做法是预热,有两种方法:
a)程序主动预热:在启动完成后,程序主动的访问热点的代码,确保主要的热点代码已被编译成机器码后再放入流量,可通过-XX:+PrintCompilation来确认。
b)复制流量预热:通过tcpcopy软件拷贝一份线上nginx的流量进行预热,完成之后再导入线上流量。
2)启动多个线程进行编译优化