java服务crash日志 jvm crash原因

转载

墨舞青云 2023-08-28 15:04:07

文章标签 java服务crash日志 jvm crash 爆栈 core文件 文章分类 Java 后端开发

一. 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 
  

# 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 ?? () 
  
 
 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) 
  
... 忽略一些信息 ...

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

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