一次tomcat启动特别慢的排查

Posted 2021-04-04 站在海边看远方

事件的起因是有一次tomcat启动，花了32分钟才启动好，非常的诡异。tomcat启动会打印一个日志:catalina.yyyy-MM-dd.log,即会生成一个带日期的日志文件，然后查看启动耗时，花了1790967ms,折合分钟是29.84945min。

这个时间肯定是不正常的，我本地调试环境一般启动耗时是1分钟左右，虽然部署到Linux上一个tomcat启动了多个应用，不过也不应该这么慢。

后来我把linux上的tomcat下载到本地，除了硬件不一样，其他都一样，然后启动耗时7分钟。

这么看，问题是出在了linux服务器上，其他的组件都是一样的，排除其他组件的问题。

然后重启linux上的进程，在本地使用jmx连接，查看启动耗时，如下图

看右上角的CPU总时间，localhost-startStop-1花了16min，点开线程看，耗时如下:

基本上是Spring Bean的加载耗时，这个也看不出啥，不过排查启动问题的时候可以查看jmx看一下。

然后回到服务器本身，使用top命令查看cpu负载:

这台机器是16核的，可是查看load average,基本上稳定在40，平均每核2.5左右，根据经验，平均每核的负载最好不要超过1，现在负载已经很高了。

然后用户占用CPU,基本稳定在96%,再看下面CPU利用率，即%CPU这一栏，并不高，所以现在问题就有点诡异。

这台机器是一个docker容器，容器数据不对，可能是宿主机出问题了，查看宿主机的CPU负载，使用top命令查看：可以看到宿主机的负载也是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资源占的差不多了。