JVM Crash排查分享 - 爆栈

一. JVM爆栈

爆栈是JVM Crash的一种案例，意思是JVM 的栈满（StackOverFlow），使得方法无法获取栈空间，而导致应用crash。爆栈是StackOverFlow的一种，只不过上层调用的是本地方法，才有可能导致出现crash，而非Native方法，则会直接抛出StackOverFlow OOM错误。

如果要分析JVM Crash的原因，需要结合Core文件可以定位导致Crash的代码。

注：在一个程序崩溃时，linux一般会在指定目录下生成一个core文件。core文件仅仅是一个内存映象(同时加上调试信息)，主要是用来调试的。

二. TradeCenter JVM Crash现象

TC运行过程中，部分机器的java进程突然就没有了，短信报警随之而来，然后紧急排查原因

 1、查看应用log，例如sys.log

结果：应用crash，应用log中没有明显的错误

 

2、查看dragoon监控，观察当时jvm运行情况，cpu，load等信息

结果：jvm运行正常；cpu和load较为平稳；网络等都正常

 

3、查看linux系统日志文件：执行dmesg或者 cat /var/log/messages

结果：日志文件存在下述错误，日志产生时间和jvm crash时间相同

java[23858]: segfault at 0000000042d76ff8 rip 00000031b140d820 rsp 0000000042d77000 error 6

 

咨询同事后得知，这是内存溢出时linux记录的日志，并且segfault 的出错地址和栈顶地址（rsp）十分接近，因此很有可能是栈内存溢出导致的。

 

三. 处理方案，产生core文件

经过第2步的分析，很有可能是栈内存溢出导致jvm crash，那么接下来就要找到应用中哪个点触发的？

 

1. 临时处理方案，利用crontab自动重启应用

由于TC进程挂掉的时间不定，为了不影响集群的稳定性，写了一个crontab定时程序，每一分钟执行一次，当java进程不存在时，自动重启应用。

 

2. 产生core文件

    2.1) 默认情况下，生产环境是不会产生core文件的。在控制台中执行如下命令：

[admin@vm-ae-qa-10 ~]$ ulimit -c
0

    为0表示，系统默认不生成core dump文件。

 

    2.2) 修改ulimit设置：

[admin@vm-ae-qa-10 ~]$ ulimit -c unlimited
[admin@vm-ae-qa-10 ~]$ ulimit -c
unlimited

    该设置仅仅在session级别生效。所以需要在当前session下重启应用，并等待jvm crash。

 

    2.3) 由于TC进程挂掉的时间不定，我们不可能一直在这里等待，需要让该设置在用户级别生效，此时你可以关闭终端，等jvm crash后再分析core文件。在admin用户根目录下执行：

vi .bash_profile

          在.bash_profile增加一行：ulimit -c unlimited，如下

# .bash_profile

# Get the aliases and functions
if [ -f ~/.bashrc ]; then
. ~/.bashrc
fi

# User specific environment and startup programs

PATH=$PATH:$HOME/bin
ulimit -c unlimited
export PATH

           2.4) 重启应用

 

    3. core文件产生位置

    TC crash以后，core文件产生在/home/admin/service/bin，即应用启动脚本所在目录。注：该路径可以配置。

 

     注意： TC集群打开core文件设置后，第一次jvm crash时，并没有产生core文件，非常奇怪。文平咨询了淘宝同学：这种情况偶尔会出现，core文件有时产生不了，多试几次就可以了。后来tc再次发生crash时，core文件在/home/admin/service/bin目录下产生，名称为：core-java-400-11-1366630975

 

四. 分析core文件，三步曲

core文件非常大，使用gdb分析该文件，排查过程分为三步：

第一步：加载core 文件：gdb -c core-java-400-11-1366630975

第二步：获取core文件中线程信息，定位jvm crash时，当前正在运行的线程：info threads

第三步：使用jstack命令分析core文件，获取指定线程id对应的代码信息：jstack /usr/alibaba/java/bin/java core.10011 |more

 

详细排查过程如下：

1. 加载core 文件，在控制台执行gdb -c core-java-400-11-1366630975，执行结果如下

....忽略一些信息....
[New process 409]
[New process 408]
[New process 407]
[New process 406]
[New process 405]
[New process 404]
[New process 403]
[New process 400]
#0 0x00002b0200688a63 in ?? ()
(gdb)

     

2. 获取core文件中线程信息，定位jvm crash时，当前正在运行的线程。在gbd后执行info threads ，如下

....忽略一些信息....
[New process 409]
[New process 408]
[New process 407]
[New process 406]
[New process 405]
[New process 404]
[New process 403]
[New process 400]
#0 0x00002b0200688a63 in ?? ()
(gdb) info threads

   此时会显示很多线程信息，按回车一直到文件最后，找到行头带*号的那一行，就是jvm crash时的线程信息

....忽略一些信息....
6 process 16720 0x0000003bc8a0a899 in ?? ()
5 process 16721 0x0000003bc8a0ab00 in ?? ()
4 process 16729 0x0000003bc8a0ab00 in ?? ()
3 process 16742 0x0000003bc8a0ab00 in ?? ()
2 process 16743 0x0000003bc8a0ab00 in ?? ()
* 1 process 1256 0x00002b0200688a63 in ?? ()

   可以看出，导致jvm crash时的线程id为1256。

3. 退出gdb，执行quit

....忽略一些信息....
4 process 16729 0x0000003bc8a0ab00 in ?? ()
3 process 16742 0x0000003bc8a0ab00 in ?? ()
2 process 16743 0x0000003bc8a0ab00 in ?? ()
* 1 process 1256 0x00002b0200688a63 in ?? ()
(gdb) quit
[admin@tradecenter-service-pub lhx]$

4. 使用jstack命令分析core文件，获取指定线程id对应的代码信息，执行如下

[admin@tradecenter-service-pub lhx]$ jstack /usr/alibaba/java/bin/java core-java-400-11-1366630975 |more

   执行结果如下：

Attaching to core core-java-400-11-1366630975 from executable /usr/alibaba/java/bin/java, please wait...
Debugger attached successfully.
Server compiler detected.
JVM version is 20.0-b11
Deadlock Detection:

No deadlocks found.

Thread 16743: (state = BLOCKED)
- sun.misc.Unsafe.park(boolean, long) @bci=0 (Compiled frame; information may be imprecise)
- java.util.concurrent.locks.LockSupport.parkNanos(java.lang.Object, long) @bci=20, line=198 (Compiled frame)
- java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill(java.util.concurrent.SynchronousQueue$TransferStack$SNode, boolean, long) @bci=174, line=424 (Compiled frame)
- java.util.concurrent.SynchronousQueue$TransferStack.transfer(java.lang.Object, boolean, long) @bci=102, line=323 (Compiled frame)
- java.util.concurrent.SynchronousQueue.poll(long, java.util.concurrent.TimeUnit) @bci=11, line=874 (Interpreted frame)
- java.util.concurrent.ThreadPoolExecutor.getTask() @bci=62, line=945 (Interpreted frame)
- java.util.concurrent.ThreadPoolExecutor$Worker.run() @bci=18, line=907 (Compiled frame)
- java.lang.Thread.run() @bci=11, line=662 (Interpreted frame)


Thread 16742: (state = BLOCKED)
- sun.misc.Unsafe.park(boolean, long) @bci=0 (Compiled frame; information may be imprecise)
... 忽略一些信息 ...

   接下来，就是搜索more出来的信息，搜索关键字1256（导致jvm crash时的线程id为1256），执行/1256，往下翻几页，可以看到下面的信息:

 

 

 

很明显，触发点找到了，在TradeFlowServiceAdaptProxy.preparePay方法发生了递归调用，最终导致爆栈。

 

至此，我们知道了jvm crash的代码块，通过结合该代码的执行场景，系统Crash的场景如下：父类中存在preparePay方法，其方法体是调用子类的preparePay，但是子类没有覆盖父类的preparePay。因此，如果去调用父类的preparePay方法...你应该懂了，如此递归调用父类preparePay方法，最终导致爆栈。

 

四. 爆栈的场景

1. 应用陷入死循环（应用吃掉异常，陷入死循环异常）；递归调用，没有结束条件
2. 栈顶存在native调用