tomcat startup blocked because stackoverflow error

spring项目在tomcat中启动时，会随机的卡死，tomcat启动失败，关闭之后重启有时就会正常启动，失败时的日志输出到如下位置时停下来，没有异常输出到控制台。

2017-02-26 17:40:05 [ RMI TCP Connection(2)-127.0.0.1:4882 ] - [ INFO ] org.springframework.context.support.AbstractApplicationContext$BeanPostProcessorChecker.postProcessAfterInitialization(AbstractApplicationContext.java:1350) Bean 'dataSource' of type [class com.example.DataSource] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)

debug时发现一直卡在spring容器AbstractAutowireCapableBeanFactory的doCreateBean和populateBean方法中：

public abstract class AbstractAutowireCapableBeanFactory extends AbstractBeanFactory
        implements AutowireCapableBeanFactory {
    // ... other codes
    protected Object doCreateBean(final String beanName, final RootBeanDefinition mbd, final Object[] args) {
        // ... other codes
        // Initialize the bean instance.
        Object exposedObject = bean;
        try {
            // 调试时一直在这里不断的递归调用
            populateBean(beanName, mbd, instanceWrapper);
            if (exposedObject != null) {
                exposedObject = initializeBean(beanName, exposedObject, mbd);
            }
        }
        catch (Throwable ex) { // spring 在此捕获了所有Exception和Error，并重新包装了一个运行时异常 BeanCreationException
            if (ex instanceof BeanCreationException && beanName.equals(((BeanCreationException) ex).getBeanName())) {
                throw (BeanCreationException) ex;
            }
            else {
                throw new BeanCreationException(mbd.getResourceDescription(), beanName, "Initialization of bean failed", ex);
            }
        }
        // ... other codes
    }
    // ... other codes
 }

碰到这个问题，第一反应是与数据库连接有关系，而且日志输出到了dataSource相关的位置停下来的，然后debug时一直不断在尝试在创建mybatis的sqlSessionFactory这个bean以及相关的一些Dao，因为多数情况下还是能正常启动tomcat的，所以数据库配置是没有问题，而且在windows开发机器上也没有发生这样的情况，只有在测试服务器linux环境和本地Mac系统中偶尔发生。

解决问题想到的相关工具和方法

打开日志DEBUG级别

因为出错时的日志一开始是INFO级别的，所以碰到问题后就设置为DEBUG级别，希望看到更详细的信息，但是与INFO级别没什么大的区别，卡死的位置也是一样的，因此日志并没有提供更多有价值的信息。

检查tomcat的相关日志文件

主要检查了catalina.out和localhost.yyyy-MM-dd.log这2个日志文件，里面也没有任何异常堆栈信息。

检查网络连接和数据库连接情况

 nestate -an | grep 3306

检查了与数据库服务器之间的网络连接情况，根本没有这样的连接，在数据库控制台中确认了一下，也没有数据连接太多的问题：

mysql> show full processlist\G

strace跟踪tomcat启动的网络连接和文件打开情况

 strace -e trace=network -f bin/startup.sh

没有与外部服务器有发生网络连接的操作，也就是这个时候还没有去连接mysql数据库，因此可以判断这个问题与数据库的连接其实并没有直接的关系，同样文件打开操作：

 strace -e trace=open -f bin/startup.sh

除了正常的tomcat日志和相关配置文件以及相关jar包的读取操作，并无异常。

top -Hp $pid && jstack

在tomcat启动卡住之后，大概几分钟之后，系统的CPU就会飚到300%以上，这也是显然很不正常的。

首先使用jcmd找到tomcat的进程号$pid：

 jcmd -l

再通过top -Hp $pid指令找到有问题的线程号：

 top -Hp $pid

显示的几个高CPU使用率的java线程对应操作系统进程的$tid，使用printf "%x\n" $tid查看在java中的线程id的16进制值，再通过jstack查看线程栈的信息，这个过程参考另一篇blog，最后发现高CPU的3个线程都是jvm的GC线程，也就是此时的tomcat进程中在不断的产生对象，不断的回收对象。

使用jvisualvm和jconsole工具查看jvm

可以使用jcmd工具查看jvm对应进程号$pid中的对象和类加载情况：

 jcmd $pid GC.class_stats | head
 jcmd $pid GC.class_histogram | head

类加载并没有什么异常，但对象创建就不太正常了，创建Object对象接近800万个，另外从jvisualvm的GC图中可以看到一直在创建新对象，并且来不及销毁，所以eden区和old generation区一直是满的，所以GC对应的3个线程一直在满负荷运作，每个GC线程消耗的CPU都是接近100%的。

然后再查看jvm的CPU主要在哪些方法调用上消耗了大量资源：

由显示结果可以看到，spring一直处理运行时异常相关的方法调用，加入断点之后，再进行调用方法栈的追溯，发现在创建sqlSessionFactory的bean时，发生了StackOverflowError的错误，并且spring在AbstractAutowireCapableBeanFactory中捕获了StackOverflowError，并转化成运行时异常，再重新抛出运行时异常BeanCreationException，在高层代码中捕获了这个运行时异常，并继续创建其他的spring的bean，而mybatis里的Dao又会依赖到sqlSessionFactory，又再次创建sqlSessionFactory这个bean，从而发生死循环了。

spring的调用方法栈截图如下，可以查看异常的产生原因，最后看到StackOverflowError的异常：

问题解决方法

既然是spring在创建bean时，因为递归调用时，造成了StackOverflowError错误，那么jvm启动时加入参数-Xss1280k(或者是-XX:ThreadStackSize=1280)，加大线程栈的容量就可以解决这个问题。在32位系统上，java Thread Stack size默认是512k，而在64位系统上则默认是1024k，这里适当调高之后，应用启动就正常了。

简单的递归调用深度测试

public class StackOverflowErrorExample {

    private int i = 1;

    private void recursiveInvoke() {
        System.out.println(i++);
        recursiveInvoke();
    }

    public static void main(String[] args) {
        StackOverflowErrorExample example = new StackOverflowErrorExample();
        example.recursiveInvoke();
    }

}

jvm启动时将-XX:ThreadStackSize分别设置为1024/1280/2048，递归调用发生StackOverflowError时的调用方法深度为：

-XX:ThreadStackSize	Recursive Times
1024	8814
1280	10976
2048	18107

GC参数设置

另外在jvm启动时加入以下GC参数，可以跟踪并查看jvm的GC运行情况。

-Dfile.encoding=UTF-8
-XX:+PrintTenuringDistribution -XX:+PrintGCDetails
-XX:+PrintGCDateStamps -XX:+PrintGCTimeStamps
-verbose:gc -Xloggc:/tmp/jvm/gc-$(date +%Y-%m-%d).log
-XX:GCLogFileSize=100M -XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=5

References

1. Spring - StackOverflowError in Bean creation
2. Spring 启动问题
3. mybatis+spring启动卡死解决方法