事件的起因是有一次tomcat启动,花了32分钟才启动好,非常的诡异。
tomcat启动会打印一个日志:catalina.yyyy-MM-dd.log
,即会生成一个带日期的日志文件,然后查看启动耗时,花了1790967ms,折合分钟是29.84945min。
这个时间肯定是不正常的,我本地调试环境一般启动耗时是1分钟左右,虽然部署到Linux上一个tomcat启动了多个应用,不过也不应该这么慢。
后来我把linux上的tomcat下载到本地,除了硬件不一样,其他都一样,然后启动耗时7分钟。
这么看,问题是出在了linux服务器上,其他的组件都是一样的,排除其他组件的问题。
然后重启linux上的进程,在本地使用jmx连接,查看启动耗时,如下图
image.png
看右上角的CPU总时间,localhost-startStop-1花了16min,点开线程看,耗时如下:
image.png
基本上是Spring Bean的加载耗时,这个也看不出啥,不过排查启动问题的时候可以查看jmx看一下。
然后回到服务器本身,使用top命令查看cpu负载:
:
这台机器是16核的,可是查看load average,基本上稳定在40,平均每核2.5左右,根据经验,平均每核的负载最好不要超过1,现在负载已经很高了。
然后用户占用CPU,基本稳定在96%,再看下面CPU利用率,即%CPU这一栏,并不高,所以现在问题就有点诡异。
这台机器是一个docker容器,容器数据不对,可能是宿主机出问题了,查看宿主机的CPU负载,使用top命令查看:
image.png
可以看到宿主机的负载也是40,下面有1个进程CPU占用1100%,基本占了11个核,问题就出在这里了。
容器是用的宿主机的硬件资源,所以查到的信息和宿主机的保持一致。
问题到这里也就清楚了,是宿主机CPU被占满,导致tomcat启动的时候分配不到CPU,启动能耗时半小时。
再来回顾一下排查过程,首先是tomcat启动耗时30分钟这个现象。
先是使用jmx观察tomcat启动耗时,只看出来时间花在哪了,但是并没有看出问题在哪。
排查启动线程耗时无果,于是在本地模拟和linux上一样的环境,观察启动耗时,在本地环境启动只花了7分钟。问题可以确认出在服务器上。
随后使用top命令观察CPU,一开始对top命令不熟悉,所以走了好多弯路,top的各项指标还是值得好好学习一下。
首先是load average,这3个值分别表示1分钟、5分钟、15分钟内系统的平均负荷,这个值单核最好不要超过1,超过1算负载很高了,需要进行排查。
然后是us,us是用户进程执行时间百分比,这个值如果长期超过50%,需要对程序进行优化。
sy是内核系统进程执行时间百分比,这个值也不宜过高。
%CPU是当前程序执行占用CPU。
其实如果对top命令的参数熟悉的话,可以很快的看出来CPU的负载长期处于飙高的状态,不仅load average高,us也高,然后就可以快速定位到问题了。
另外涉及到docker的话,如果出现负载高,但是%CPU列值不高的情况,可以去查看一下宿主机的状态。本次就是宿主机有1个进程把CPU资源占的差不多了。
网友评论