问题现象:
在项目在tomcat部署过程中,tomcat启动失败,经检查只打印了
09-Jan-2020 03:31:49.582 INFO [localhost-startStop-30] org.apache.catalina.startup.HostConfig.deployDirectory Deployment of web application directory [/opt/xxx/tomcat/webapps/myapp] has finished in [148,468] ms
未打印tomcat结束时Server startup 日志:
09-Jan-2020 03:31:49.589 INFO [main] org.apache.coyote.AbstractProtocol.start Starting ProtocolHandler ["http-nio-8080"]
09-Jan-2020 03:31:49.603 INFO [main] org.apache.catalina.startup.Catalina.start Server startup in 148573 ms
第一次尝试解决
经过网上搜索解决方案如下:
https://jingyan.baidu.com/article/4f34706e126f51e386b56d5f.html
即
查阅大量资料发现是由于tomcat启动时产生随机数导致jvm阻塞,可能是我多次重启tomcat导致熵池被用空造成阻塞。。
在apache-tomcat官方文档:如何让tomcat启动更快里面提到了一些启动时的优化项,其中一项是关于随机数生成时,采用的“熵源”(entropy source)的策略。他提到tomcat7的session id的生成主要通过java.security.SecureRandom生成随机数来实现,随机数算法使用的是”SHA1PRNG”
打开$JAVA_PATH/jre/lib/security/java.security这个文件,找到下面的内容:
securerandom.source=file:/dev/urandom大概在70行 ,替换成
securerandom.source=file:/dev/./urandom
第一次解决效果
重启之后项目正常启动。
多次测试重启后,发现阻塞偶尔还是存在,但概率貌似减少了。
既然阻塞还是存在,说明问题没有解决,是解决的步骤不对,还是没有找问题的根源呢。
寻找问题根源
如果是uuid问题,应该也有代码调用,那这个random在什么时候调用呢。还是读一读源码把。
经过一下阅读和研究,没有找到random的的源码,但找到了部署context如下源码:
/**
* Deploy exploded webapps.
* @param appBase The base path for applications
* @param files The exploded webapps that should be deployed
*/
protected void deployDirectories(File appBase, String[] files) {
if (files == null)
return;
ExecutorService es = host.getStartStopExecutor();
List<Future<?>> results = new ArrayList<>();
for (int i = 0; i < files.length; i++) {
if (files[i].equalsIgnoreCase("META-INF"))
continue;
if (files[i].equalsIgnoreCase("WEB-INF"))
continue;
File dir = new File(appBase, files[i]);
if (dir.isDirectory()) {
ContextName cn = new ContextName(files[i], false);
if (isServiced(cn.getName()) || deploymentExists(cn.getName()))
continue;
results.add(es.submit(new DeployDirectory(this, cn, dir)));
}
}
for (Future<?> result : results) {
try {
result.get();
} catch (Exception e) {
log.error(sm.getString(
"hostConfig.deployDir.threaded.error"), e);
}
}
}
对源码进行分析可得:tomcat通过多线程的方式部署webapps, 而且使用的callable方式,最后会通过get方法确认webapps是否部署完成。
核对catalina的日志发现,确实有1个webApp未报如下日志
org.apache.catalina.startup.HostConfig.deployDirectory Deployment of web application directory [/opt/xxx/tomcat/webapps/xxx] has finished in [148,468] ms
继续刨根问底
问题终于快要浮出水面了,让我们一探究竟,是什么导致该线程没有执行完,阻塞了呢。
过程就直接省略了把,直接说结果吧。
tomcat启动webapps时的线程执行中,初始化了spring的bean。
在内部开发人员提供的第三方jar包初始化bean的时候用了@Postconstruct
注解进行了第三方请求的调用,调用中执行了无限等待,第三方的服务又没起来,导致了线程阻塞。
修改方式
将初始化连接第三方应用的内容改为异步的就行了。因为改不动jar包。
结果
项目正常启动,再也没有阻塞了。
另外一次阻塞排查
后面项目启动中发现项目又一次阻塞了,按照之前的排查经验,找到了根源。
同事直接把@Postconstruct
和@Async
一起用了,但这时@Async
不会起作用,执行不会用异步的线程还是tomcat启动的主线程。
修改,使用ApplicationRuner
接口和@Async
,项目成功多线程执行。
分析原因:@Postconstruct
是在加载bean的时候执行,ApplicationRuner
是在所有bean加载完后执行。@Postconstruct
执行的代码不对检测@Async
注解,直接使用启动线程执行。