使用strace定位jvm退出的原因范围

今天遇到的一个tomcat启动过程中jvm退出的问题,不是jvm crash的情况,用户日志配置的不正确导致一些信息没有展现出来,只看到pandora执行了shutdownhook的信息。这可能是启动时的逻辑有触发System.exit,或被系统或人为kill掉了。

根据以往的经验,排除了oom killer或ulimit -t设置不当导致被内核给kill掉的情况,OS级别的signal通常不留机会给jvm执行shutdownhook的。如此一来singal的范围应该就是SIGTERM, SIGINT, SIGHUP这3种(参考这里)。

虽然singal范围缩小,但依然不能确定是因为代码里调用了System.exit还是人为(或被其他进程)kill引起的。直接上大招用systemtap需要安装kernal debuginfo,没有权限的话,还要找到对应的人去做;如果现象较容易重现的话,可以先通过strace命令进一步缩小问题的范围,究竟是因为jvm内部执行了System.exit还是外界的kill引起的。

这里通过启动一个scala的repl来模拟java进程,通过strace attach到jvm进程上,然后观察,如果是外界的kill所致,可以看到下面的信息:

$ sudo strace -p 1947
Process 1947 attached - interrupt to quit
futex(0x7fb7635959d0, FUTEX_WAIT, 1948, NULL) = ? ERESTARTSYS (To be restarted)
--- SIGTERM (Terminated) @ 0 (0) ---
futex(0x7fb762762360, FUTEX_WAKE_PRIVATE, 1) = 1
rt_sigreturn(0x7fb762762360)            = 202
futex(0x7fb7635959d0, FUTEX_WAIT, 1948, NULLPANIC: attached pid 1947 exited with 143
 <unfinished ... exit status 143>

里面的关键信息是SIGTERMexit status 143(即SIGTERM的code)

如果是kill -2或ctrl-c终止repl,可以看到有关SIGINT的信息

$ sudo strace -p 1813
Process 1813 attached - interrupt to quit
futex(0x7fb24d15a9d0, FUTEX_WAIT, 1814, NULL) = ? ERESTARTSYS (To be restarted)
--- SIGINT (Interrupt) @ 0 (0) ---
futex(0x7fb24c327360, FUTEX_WAKE_PRIVATE, 1) = 1
rt_sigreturn(0x7fb24c327360)            = 202
futex(0x7fb24d15a9d0, FUTEX_WAIT, 1814, NULLPANIC: attached pid 1813 exited with 130
 <unfinished ... exit status 130>

如果是jvm自身执行了System.exit比如:

scala> System.exit(0)

那么在跟踪的信息里,是看不到signal的:

$ sudo strace -p 2131
Process 2131 attached - interrupt to quit
futex(0x7fc14adb49d0, FUTEX_WAIT, 2132, NULLPANIC: attached pid 2131 exited with 0
 <unfinished ... exit status 0>

至此我们可以判断出到底是外部还是内部引起的了,如果是内部就不必麻烦Systemtap了,可以从源码去找。

jvm与系统信号(4)

stop 与 cont 信号

这两个信号对于jvm也是可用的,比如让jvm进程停止:

scala> var a=0;

scala>  while(true) { Thread.sleep(2000); println(a); a=a+1 }
0
1
2
3

$ ps -ostat -p `pidof java`
STAT
S+

$ kill -s stop `pidof java`

此时jvm进程被暂停住,进程状态也变为:T (TASK_STOPPED or TASK_TRACED),暂停状态或跟踪状态

$ ps -ostat -p `pidof java`
STAT
T+

发送cont信号恢复进程状态:

$ kill -s cont `pidof java`

repl端会继续输出。

jvm与系统信号(3)

一些相关的参数

1) -Xrs

man java里可以看到这个参数的介绍,大意如下:

这个参数是在java1.3.1 之后增加的,rs是reduce signal的缩写,即忽略系统信号。在java1.3.0添加了 Shutdown Hook,目的是用于在jvm关闭时清除一些代码(比如关闭数据库连接)。对于jvm非正常退出,Sun/Oracle的jvm通过捕获信号来实现shutdown hook。JVM使用 SIGHUP, SIGINT,SIGTERM 来初始化 shutdown hook

JVM使用了相似的机制来实现 pre-1.2 特性,dumping线程栈(用于调试目的)。Sun/Oracle的JVM使用 SIGQUIT 来执行 线程 dump.

应用时常也需要自己捕获SIGINT或SIGTERM,这会导致干扰JVM自己的signal handler,为了避免这种情况, -Xrs 命令行参数在java1.3.1里被增加了进来。当使用 Sun的JVM时, SIGINT, SIGTERM, SIGHUP, SIGQUIT不会被影响JVM,这些信号的handler不会被install。

使用-Xrs要注意这2个后果:

1) SIGQUIT 不再产生 thread dump
2) Shutdown hook将不被执行

尝试一下Xrs参数,使用scala -J-Xrs启动一个repl:

$ scala -J-Xrs

$ kill -3 `pidof java` 

这个时候确实不会产生 thread dump,并且java进程会退出。

有趣的是,我使用 jstack 依然可以看到 scala repl的所有线程,也就是jstack依然会把请求发送到java进程,即使它设置了-Xrs,可能与attach机制有关,这里的细节以后再展开。

2) -XX:-AllowUserSignalHandlers

限于Linux和Solaris,默认不启用。允许为java进程安装信号处理器,信号处理参见类:sun.misc.Signal, sun.misc.SignalHandler

3) -XX:+UseAltSigs

限于Solaris,默认启用。为了防止与其他发送信号的应用程序冲突,允许使用候补信号替代 SIGUSR1和SIGUSR2