一、背景
问题:有一个springboot项目部署在Tomcat/8.5.38里面,发现每隔15s左右tomcat重启一次
服务器信息:
- CentOS release 6.5
- java version "1.8.0_60"
- Apache Tomcat/8.5.38
二、发现问题
发现这个问题是很意外的,一开始只是看到服务器内存快要用完了,当时并没有考虑到可能出了什么问题,只是想着如果实在不行就升级服务器内存。下图是当时服务器内存的情况。
[root@iZbp19zv1tu402bo15tpq9Z log]# free -lm
total used free shared buffers cached
Mem: 7872 7115 757 0 261 2918
Low: 7872 7115 757
High: 0 0 0
-/+ buffers/cache: 3935 3937
Swap: 0 0 0
问题是这样被发现的,有一天我想看一下日志,打开日志的时候却发现有很多条启动日志,大概每隔15s左右就重启一次,正常情况下并不会重启才对。
11:03:54 [localhost-startStop-1] INFO org.apache.jasper.servlet.TldScanner - At least one JAR was scanned for TLDs yet contained no TLDs. Enable debug logging for this logger for a complete list of JARs that were scanned but no TLDs were found in them. Skipping unneeded JARs during scanning can improve startup time and JSP compilation time.
11:03:54 [localhost-startStop-1] INFO o.s.b.c.e.AnnotationConfigEmbeddedWebApplicationContext - Closing org.springframework.boot.context.embedded.AnnotationConfigEmbeddedWebApplicationContext@336d2b9b: startup date [Sat Oct 12 11:03:46 CST 2019]; root of context hierarchy
11:03:54 [localhost-startStop-1] INFO o.s.c.s.DefaultLifecycleProcessor - Stopping beans in phase 2147483647
11:03:55 [localhost-startStop-1] INFO o.s.c.s.DefaultLifecycleProcessor - Stopping beans in phase -2147482648
11:03:55 [localhost-startStop-1] INFO o.s.j.e.a.AnnotationMBeanExporter - Unregistering JMX-exposed beans on shutdown
11:03:55 [localhost-startStop-1] INFO o.s.j.e.a.AnnotationMBeanExporter - Unregistering JMX-exposed beans
11:03:55 [localhost-startStop-1] INFO c.alibaba.druid.pool.DruidDataSource - {dataSource-1} closed
通过观察日志,发现tomcat重启是因为我用了supervisor去监控tomcat,如果tomcat异常退出就自动重启。
11:04:19 [localhost-startStop-1] INFO org.xx.boot.XxBootAppliaction - Starting XxBootAppliaction on iZbp19zv1tu402bo15tpq9Z with PID 813 (/data/tomcat/ihomepay/webapps/ihomepayapi/WEB-INF/classes started by root in /etc/supervisor/conf.d)
其实很早之前我查看supervisor的监控状态,就发现tomcat-ihomepay经常是start状态,但项目运行正常,以为是supervisor的问题,就忽略了,现在再仔细看,的确运行15s左右又重新启动了。下图是查看通过supervisor监控的项目的启动状态,服务器上部署了两个tomcat,出问题的是tomcat-ihomepay这个,可以看到pid经常变化,uptime都是几秒,证实了服务在不断重启。
[root@iZbp19zv1tu402bo15tpq9Z log]# supervisorctl status
tomcat-ihomepay RUNNING pid 8444, uptime 0:00:07
tomcat-nwcl RUNNING pid 22640, uptime 19:32:06
三、解决问题
意外发现了这个问题,这下有意思了。
思路1:supervisor配置不对?
一开始首先考虑的是会不会是supervisor关于tomcat的配置不对,但看了没发现问题,这个配置和另外一个正常运行的tomcat配置没有不同。
[program:tomcat-ihomepay]
command=/data/tomcat/ihomepay/bin/catalina.sh run
stdout_logfile=/data/tomcat/ihomepay/logs/catalina.out
autostart=true
autorestart=true
startsecs=5
priority=1
stopasgroup=true
killasgroup=true
思路2:tomcat版本和springboot项目冲突?
然后根据关键词Unregistering JMX-exposed beans on shutdown
和Unregistering JMX-exposed beans
百度了一下,发现搜出来的答案都是说pom.xml打包的问题,但对我这个情况没有帮助,我的项目已经是下面的配置了。
<dependency>
<groupId>org.springframework.boot</groupId>
<artifactId>spring-boot-starter</artifactId>
</dependency>
上面这段pom改成下面试下,(https://stackoverflow.com/questions/22380119/why-my-spring-boot-app-always-shutdown)
<dependency>
<groupId>org.springframework.boot</groupId>
<artifactId>spring-boot-starter-web</artifactId>
</dependency>
思路3:服务器内存不足,自动关闭了进程?
接着开始考虑是不是java内存溢出自动关闭了tomcat,想找相关的日志,但不知道怎么找。
百度找到这篇文章,发现和我的问题有相关性https://blog.csdn.net/qq_35981283/article/details/62233725
但我执行sudo dmesg -T | grep "(java)"
这个命令会报错。
[root@iZbp19zv1tu402bo15tpq9Z ~]# dmesg -T | grep "(java)"
dmesg: invalid option -- 'T'
Usage: dmesg [-c] [-n level] [-r] [-s bufsize]
虽然命令没有执行成功,但提供了一个思路给我,通过top
命令去查看java相关的进程,看占用的内存大小是否出现异常。
top命令参考https://blog.csdn.net/qq_31860135/article/details/83620093
通过top命令查看并按使用内存就行排序,发现有好几个java进程
查看某个进程的详细信息,竟然发现有进程重复启动了。
两个tomcat都分别有两个进程在启动
ps -aux | grep -v grep |grep 13154
网上查找了以下,发现有相关的文章也提到tomcat重复启动这个问题。
https://blog.csdn.net/qq_26684469/article/details/78758465
ps aux|head -1;ps aux|grep -v PID|sort -rn -k +4|head
看了一下tomcat进程的启动时间,有两个是在很久之前启动的,另两个是最近启动的,因为最近有重启过。这时恍然大悟,之前安装supervisor管理tomcat的时候,没有把之前的tomcat进程清理干净,导致之前和进程和supervisor启动的进程重复了,这也导致服务器使用内存变大了。
解决方法:直接把不是由supervisor启动的两个tomcat进程杀掉就行了。
kill -9 13154
现在查看tomcat的运行状态正常了,内存也正常了。
[root@iZbp19zv1tu402bo15tpq9Z log]# supervisorctl status
tomcat-ihomepay RUNNING pid 19581, uptime 0:39:45
tomcat-nwcl RUNNING pid 22640, uptime 21:14:36
[root@iZbp19zv1tu402bo15tpq9Z bin]# free -lm
total used free shared buffers cached
Mem: 7872 6309 1563 0 256 3553
Low: 7872 6309 1563
High: 0 0 0
-/+ buffers/cache: 2498 5373
Swap: 0 0 0
四、总结
学海无涯,从入门到放弃