1 背景介绍
某日某客户运维工程师接收到系统报障反应业务缓慢，工程师用命令kill -3 < WLS_PID >的方式发送一个SIGQUIT信号给Java应用之后，通常会有当前的Thread Dump输出，最后thread dump信息没有收集出来，相反weblogic进程自动退出，导致服务停止，业务无法正常工作。
2 系统环境
操作系统： Redhat6.4
JDK版本： JDK1.6
中间件版本：weblogic10.3.6
集群：否
3 故障处理过程
3.1故障分析
2016-09-13 15:23左右，客户现场运维工程师接收到报障反应系统访问相当慢，于是运维工程师立即检查中间件运行情况，并做了一下线程转储收集。在做线程转储收集时候，服务被终止。现场工程师说当时执行了kill -3 <WLS_PID>这条命令来收集thread dump信息，没想到竟然把weblogic服务进程给杀掉了。他说以前平时常用kill -3来收集线程信息，今天竟奇怪的把服务给干掉了。他也反复确认操作的命令没错。
<Sep 11, 2016 4:09:36 PM CST> <Notice> <WebLogicServer> <BEA-000365> <Server state changed to STANDBY> <Sep 11, 2016 4:09:36 PM CST> <Notice> <WebLogicServer> <BEA-000365> <Server state changed to STARTING> <Sep 11, 2016 4:09:40 PM CST> <Notice> <Log Management> <BEA-170027> <The Server has established connection with the Domain level Diagnostic Service successfully.> <Sep 11, 2016 4:09:40 PM CST> <Notice> <WebLogicServer> <BEA-000365> <Server state changed to ADMIN> <Sep 11, 2016 4:09:40 PM CST> <Notice> <WebLogicServer> <BEA-000365> <Server state changed to RESUMING> <Sep 11, 2016 4:09:40 PM CST> <Notice> <Server> <BEA-002613> <Channel "Default" is now listening on 192.168.106.100:9001 for protocols iiop, t3, ldap, snmp, http.> <Sep 11, 2016 4:09:40 PM CST> <Notice> <WebLogicServer> <BEA-000329> <Started WebLogic Admin Server "bps_Server1" for domain "bps_domain" running in Production Mode> <Sep 11, 2016 4:09:40 PM CST> <Notice> <WebLogicServer> <BEA-000365> <Server state changed to RUNNING> <Sep 11, 2016 4:09:40 PM CST> <Notice> <WebLogicServer> <BEA-000360> <Server started in RUNNING mode> Quit (core dumped) <<进程退出信号 |
发现故障时间15:24产生了一个core dump文件，应该是kill -3信号产生的文件。
weblogic@bps_prod:~/weblogic11g/user_projects/domains/bps_domain> ls -lrt total 1132 drwxr-x--- 2 weblogic weblogic 4096 Aug 31 14:34 lib drwxr-x--- 2 weblogic weblogic 4096 Aug 31 14:34 console-ext drwxr-x--- 2 weblogic weblogic 4096 Aug 31 14:34 autodeploy drwxr-x--- 2 weblogic weblogic 4096 Aug 31 14:34 security -rwxr-x--- 1 weblogic weblogic 277 Aug 31 14:34 startWebLogic.sh -rw-r----- 1 weblogic weblogic 736 Aug 31 14:34 startManagedWebLogic_readme.txt drwxr-x--- 2 weblogic weblogic 4096 Aug 31 14:34 init-info -rw-r----- 1 weblogic weblogic 462 Aug 31 14:34 fileRealm.properties drwxr----- 7 weblogic weblogic 4096 Sep 1 02:01 servers -rw-r----- 1 weblogic weblogic 235 Sep 9 14:01 shutdown.py drwxr----- 2 weblogic weblogic 4096 Sep 10 21:43 tmp drwxr----- 2 weblogic weblogic 4096 Sep 10 21:44 pending -rw-r----- 1 weblogic weblogic 32 Sep 10 21:44 edit.lok drwxr-x--- 10 weblogic weblogic 4096 Sep 10 22:01 config -rw------- 1 weblogic weblogic 1224704 Sep 13 15:24 core <<kill 信号3 产生的core文件 |
分析产生的core文件，没有找到完整的信息
weblogic@bps_prod:~/weblogic11g/user_projects/domains/bps_domain> gdb /u01/jdk1.7.0_80/bin/java core GNU gdb (GDB) SUSE (7.3-0.6.1) Copyright (C) 2011 Free Software Foundation, Inc. License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html> This is free software: you are free to change and redistribute it. There is NO WARRANTY, to the extent permitted by law. Type "show copying" and "show warranty" for details. This GDB was configured as "x86_64-suse-linux". For bug reporting instructions, please see: <http://www.gnu.org/software/gdb/bugs/>... Reading symbols from /u01/jdk1.7.0_80/bin/java...Missing separate debuginfo for /u01/jdk1.7.0_80/bin/java Try: zypper install -C "debuginfo(build-id)=b82a586842f6da3df8a61093daadf04180e85c16" (no debugging symbols found)...done. BFD: Warning: /u01/weblogic/weblogic11g/user_projects/domains/bps_domain/core is truncated: expected core file size >= 501276672, found: 1224704. [New LWP 20758] [New LWP 20759] [New LWP 20760] [New LWP 20761] [New LWP 20762] [New LWP 20763] [New LWP 20764] [New LWP 20769] [New LWP 20771] [New LWP 20773] [New LWP 20775] [New LWP 20776] [New LWP 20777] [New LWP 20778] [New LWP 20779] [New LWP 20780] [New LWP 20782] [New LWP 20783] Cannot access memory at address 0x7f4fc97f5188 Failed to read a valid object file image from memory. Core was generated by `/u01/jdk1.7.0_80/bin/java -server -Xms256m -Xmx512m -XX:MaxPermSize=256m -Dwebl'. Program terminated with signal 3, Quit. #0 0x00007f4fc93bff95 in ?? () (gdb) bt #0 0x00007f4fc93bff95 in ?? () Cannot access memory at address 0x7fff021dec40 |
联想起以前处理过类似问题，weblogic进程自动退出。不想要操作系统调用正在终止JVM进程。 当某个组件将不正确的关闭信号发送到JVM时会发生此问题。 然后，JVM捕获这些信号，并关闭所有JAVA进程。
<Notice> <WebLogicServer> <domain_name> <server_name> <Thread-1> ... <BEA-000388> <JVM called WLS shutdown hook. The server will force shutdown now> |
当时解决这个问题方法是，将-Xrs参数添加到标准WebLogic启动脚本中的JAVA_OPTIONS启动参数中。
为什么要加-Xrs参数的原因？
参数-Xrs是为了避免JVM对操作系统信号的使用。 这个参数告诉JVM不要为许多事情使用任何操作系统信号，而是依靠加载应用程序（启动器）来处理TERM，INT; HUP和QUIT。如果JVM作为服务运行，它可以接收CTRL_LOGOFF_EVENT，但不应该启动关闭，因为操作系统不会实际终止进程。
回过头来检查domain下的启动环境变量脚本，发现2016-09-07 22:23这个时间点setDomainEnv.sh环境变量脚本有改动过，而且在JAVA_OPTIONS变量后确实加入了参数-Xrs.
经过自己在几个不同版本测试环境下测试，加了这个-Xrs参数确实用kill -3会把服务进程杀死。不加这个-Xrs参数用kill -3不会把进程杀死，也能够收集thread dump信息。
3.2 故障原因
将-Xrs参数添加到标准WebLogic启动脚本中的JAVA_OPTIONS启动参数中，如果用kill -3命令去收集thread dump信息，直接会触发操作系统信号杀掉服务进程。
4 解决方案
由于大家常用习惯用kill-3命令来收集线程转储信息，导致出现这样的问题。记住以后在生产系统kill尽量不用，不管kill后面带什么信号参数，不建议在生产环境上面执行。
以下是抓取threaddump常用方法
1）JVM 自带的工具获取线程堆栈:
$JAVA_HOME/bin/jstack wls_pid
2）WebLogic 自带的获取 thread dump的工具:
<DOMAIN_HOME>/bin/setDomainEnv.sh
$JAVA_HOME/bin javaweblogic.Admin -url t3://localhost:9001 -username weblogic -password weblogic1THREAD_DUMP
3）使用utils.ThreadDumper
java -cpC:\bea\wlserver_10.3\server\lib\weblogic.jar utils.ThreadDumper
4）使用weblogic console方法生成
a. 登录 Admin Console , 点击对应的服务器
b. 点击Server à Monitoring àThreads
c. 点击: Dump Thread Stack 按钮
5）使用WLST工具
java weblogic.WLSTthreaddump.py
