背景

上周末,我一个朋友来到我家,抛给我一个“Tomcat无缘故跑死”的问题,场景即是:

1
2
3
早上启动Tomcat,到了下午8点左右,Tomcat突然崩溃死掉,并且这段时间也没有做一些额外的操作。

这种事情,连续出现了好几次。

排查

由于是不在他的工作环境下,没法远程到服务器查看相关日志等。于是只能拿着他的电脑,本地分析一波。

使用VisualVM分析

于是,我让他打开VisualVM,进行监测,看看JVM内存、CPU等是否正常。监控了一段时间,发现一直如下图:

很明显,垃圾回收、CPU、线程等均正常。并且程序活得好好的。

复现异常

看来这样是不能还原出现异常的场景。于是问了下他,这个程序是主要是用来干嘛的,他说是用来爬数据的。基于restful的接口,用户调用一次接口,进行一次爬取

于是,试着使用Postman做了一下简单的压测:

这时发现VisualVM出现了异常,发现线程一栏图表内,线程数直线上升。而cpu、堆等没有太大变化。并且线程一栏中也能看到线程一直在涨( ̄︶ ̄)↗ :

紫色的Thread-xx即是不断新增的线程,并且从命名来看,也可知道:一般是开发者没有调用setName命名线程的默认名称。

因此定位到大概是开发者根据每个请求,开了子线程处理该请求。随着请求增多,线程也不断增多,一般情况下,线程执行完就会结束,而VisualVM显示线程一直在不断增加,说明这些线程一直处于忙碌、等待或阻塞等状态。

分析hs_err_pid文件

压测跑了一会儿,果不其然,tomcat死掉了。我们知道当JVM发生致命错误导致崩溃时,会生成一个hs_err_pid_xxx.log文件。

默认情况下,该文件是生成在工作目录下的,当然也可以通过 JVM 参数指定生成路径:

1
-XX:ErrorFile=/var/log/hs_err_pid<pid>.log

这个文件主要包含如下内容:

1
2
3
4
5
6
7
8
9
10
11
12
日志头文件
导致 crash 的线程信息
所有线程信息
安全点和锁信息
堆信息
本地代码缓存
编译事件
gc 相关记录
优化、异常事件
jvm 内存映射
jvm 启动参数
服务器信息

于是,分析一波:

日志头文件

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
#
# A fatal error has been detected by the Java Runtime Environment:
#
# EXCEPTION_ACCESS_VIOLATION (0xc0000005) at pc=0x00000000771ff23c, pid=4256, tid=3172
#
# JRE version: Java(TM) SE Runtime Environment (8.0_60-b27) (build 1.8.0_60-b27)
# Java VM: Java HotSpot(TM) 64-Bit Server VM (25.60-b23 mixed mode windows-amd64 compressed oops)
# Problematic frame:
# C [ntdll.dll+0x4f23c]
#
# Failed to write core dump.
#
# If you would like to submit a bug report, please visit:
# http://bugreport.java.com/bugreport/crash.jsp
# The crash happened outside the Java Virtual Machine in native code.
# See problematic frame for where to report the bug.
#

这段内容主要简述了导致 JVM Crash 的原因。常见的原因有 JVM 自身的 bug,应用程序错误,JVM 参数,服务器资源不足,JNI 调用错误等。当然还有一些版本和配置信息。

1
EXCEPTION_ACCESS_VIOLATION (0xc0000005) at pc=0x00000000771ff23c, pid=4256, tid=3172
  • 该描述表示 JVM Crash 时正在执行 JVM 自身的代码,这往往是因为 JVM的问题 导致的 Crash;另一种常见的描述是EXCEPTION_STACK_OVERFLOW,该描述表示这是个栈溢出导致的错误,这往往是应用程序中存在深层递归导致的。
  • 0xb :信号码
  • pc=0x0000003797807a91 :程序计数器的值
  • pid=29071 :进程号
  • tid=139901421901568 :线程号

当前线程信息

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
Current thread (0x00000000586f4000):  JavaThread "Thread-139" daemon [_thread_in_native, id=3172, stack(0x000000008b840000,0x000000008b940000)]

siginfo: ExceptionCode=0xc0000005, reading address 0x00000cb48c67c238
....省略
Java frames: (J=compiled Java code, j=interpreted, Vv=VM code)
j java.net.Inet6AddressImpl.lookupAllHostAddr(Ljava/lang/String;)[Ljava/net/InetAddress;+0
j java.net.InetAddress$2.lookupAllHostAddr(Ljava/lang/String;)[Ljava/net/InetAddress;+4
j java.net.InetAddress.getAddressesFromNameService(Ljava/lang/String;Ljava/net/InetAddress;)[Ljava/net/InetAddress;+51
J 8449 C1 java.net.InetAddress.getAllByName0(Ljava/lang/String;Ljava/net/InetAddress;Z)[Ljava/net/InetAddress; (57 bytes) @ 0x0000000002e934ec [0x0000000002e932a0+0x24c]
J 8452 C1 java.net.InetAddress.getAllByName(Ljava/lang/String;Ljava/net/InetAddress;)[Ljava/net/InetAddress; (387 bytes) @ 0x000000000326876c [0x0000000003266900+0x1e6c]
J 9537 C2 com.squareup.okhttp.internal.http.HttpEngine.connect()V (89 bytes) @ 0x00000000034eee8c [0x00000000034ed660+0x182c]
J 9653 C2 com.squareup.okhttp.internal.http.HttpEngine.sendRequest()V (457 bytes) @ 0x0000000003552de4 [0x000000000354f440+0x39a4]
J 9679 C2 com.squareup.okhttp.Call.getResponse(Lcom/squareup/okhttp/Request;Z)Lcom/squareup/okhttp/Response; (378 bytes) @ 0x000000000352c46c [0x000000000352c340+0x12c]
J 9565 C2 com.xxx.IDRI.restful.util.OkhttpUtils.okGet(Ljava/lang/String;)Lcom/squareup/okhttp/Response; (54 bytes) @ 0x000000000351ffd4 [0x000000000351ea40+0x1594]
j com.xxx.IDRI.whzwfw.scszfcxjs.WhLoginRestFul$1.run()V+2
J 8768 C1 java.lang.Thread.run()V (17 bytes) @ 0x00000000032d69bc [0x00000000032d6880+0x13c]
v ~StubRoutines::call_stub

--------------- P R O C E S S ---------------

Java Threads: ( => current thread )
0x000000005aca5000 JavaThread "Thread-186" daemon [_thread_blocked, id=2132, stack(0x00000000944c0000,0x00000000945c0000)]
0x0000000058816000 JavaThread "Thread-185" daemon [_thread_blocked, id=2988, stack(0x0000000090b60000,0x0000000090c60000)]
0x0000000058f69800 JavaThread "Thread-184" daemon [_thread_in_native, id=5160, stack(0x0000000094ec0000,0x0000000094fc0000)]
0x0000000067a13800 JavaThread "Thread-183" daemon [_thread_blocked, id=2876, stack(0x0000000094ca0000,0x0000000094da0000)]
0x000000005c8a5800 JavaThread "Thread-182" daemon [_thread_blocked, id=2916, stack(0x0000000094990000,0x0000000094a90000)]
0x000000005c022800 JavaThread "Thread-181" daemon [_thread_blocked, id=6020, stack(0x0000000094770000,0x0000000094870000)]
0x000000005c8a2000 JavaThread "Thread-180" daemon [_thread_blocked, id=5860, stack(0x0000000094aa0000,0x0000000094ba0000)]
0x000000005879d000 JavaThread "Thread-179" daemon [_thread_blocked, id=5764, stack(0x0000000090500000,0x0000000090600000)]
0x0000000058fef800 JavaThread "Thread-178" daemon [_thread_blocked, id=5616, stack(0x000000007e6c0000,0x000000007e7c0000)]
....省略

这部分内容包含触发 JVM 致命错误的线程详细信息和线程栈。到这里就基本上已经确定了问题所在原因了。可以看到当前线程正在使用 okhttp 进行网络请求,但是在connect()方法出现了问题,并且其他线程同样处于_thread_blocked状态,即阻塞状态,除了该状态,还有:

1
2
3
4
5
6
7
_thread_uninitialized:线程还没有创建,它只在内存原因崩溃的时候才出现
_thread_new:线程已经被创建,但是还没有启动
_thread_in_native:线程正在执行本地代码,一般这种情况很可能是本地代码有问题
_thread_in_vm:线程正在执行虚拟机代码
_thread_in_Java:线程正在执行解释或者编译后的Java代码
_thread_blocked:线程处于阻塞状态
…_trans:以_trans结尾,线程正处于要切换到其它状态的中间状态

基本就可以确定:大概是程序给每个请求分配一个或多个线程进行网络请求(可能就是爬虫),但是线程在进行网络请求时,可能是由于网络原因,也可能是线程太多导致的人家服务器的拒绝服务等原因,让线程一直处于“阻塞”状态(即一直阻塞在本地代码执行处:java.net.Inet6AddressImpl.lookupAllHostAddr()是一个本地方法),同时其他线程都处于阻塞状态!

gc 相关记录

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
Heap:
PSYoungGen total 165888K, used 64289K [0x00000000eab00000, 0x00000000f5580000, 0x0000000100000000)
eden space 157184K, 37% used [0x00000000eab00000,0x00000000ee3dba00,0x00000000f4480000)
from space 8704K, 69% used [0x00000000f4480000,0x00000000f4a6cca8,0x00000000f4d00000)
to space 8704K, 0% used [0x00000000f4d00000,0x00000000f4d00000,0x00000000f5580000)
ParOldGen total 349696K, used 86434K [0x00000000c0000000, 0x00000000d5580000, 0x00000000eab00000)
object space 349696K, 24% used [0x00000000c0000000,0x00000000c5468a30,0x00000000d5580000)
Metaspace used 79174K, capacity 80154K, committed 80560K, reserved 1120256K
class space used 9280K, capacity 9564K, committed 9648K, reserved 1048576K
...省略
GC Heap History (10 events):
Event: 4028.462 GC heap before
{Heap before GC invocations=160 (full 3):
PSYoungGen total 165888K, used 163652K [0x00000000eab00000, 0x00000000f5580000, 0x0000000100000000)
eden space 157184K, 100% used [0x00000000eab00000,0x00000000f4480000,0x00000000f4480000)
from space 8704K, 74% used [0x00000000f4d00000,0x00000000f53512c8,0x00000000f5580000)
to space 8704K, 0% used [0x00000000f4480000,0x00000000f4480000,0x00000000f4d00000)
ParOldGen total 349696K, used 85482K [0x00000000c0000000, 0x00000000d5580000, 0x00000000eab00000)
object space 349696K, 24% used [0x00000000c0000000,0x00000000c537aa20,0x00000000d5580000)
Metaspace used 79173K, capacity 80154K, committed 80560K, reserved 1120256K
class space used 9280K, capacity 9564K, committed 9648K, reserved 1048576K
Event: 4028.480 GC heap after
Heap after GC invocations=160 (full 3):
PSYoungGen total 165888K, used 7199K [0x00000000eab00000, 0x00000000f5580000, 0x0000000100000000)
eden space 157184K, 0% used [0x00000000eab00000,0x00000000eab00000,0x00000000f4480000)
from space 8704K, 82% used [0x00000000f4480000,0x00000000f4b87f08,0x00000000f4d00000)
to space 8704K, 0% used [0x00000000f4d00000,0x00000000f4d00000,0x00000000f5580000)
ParOldGen total 349696K, used 85682K [0x00000000c0000000, 0x00000000d5580000, 0x00000000eab00000)
object space 349696K, 24% used [0x00000000c0000000,0x00000000c53aca30,0x00000000d5580000)
Metaspace used 79173K, capacity 80154K, committed 80560K, reserved 1120256K
class space used 9280K, capacity 9564K, committed 9648K, reserved 1048576K
}
...省略

顺便也看一下GC情况以及最近10次GC记录。
PSYoungGenParOldGen可知道,垃圾回收使用的是Parallel Scavenge+Parallel Old的并行回收组合。
eden区、from区、to区、old区等均正常。

异常事件

1
2
3
4
Internal exceptions (10 events):
Event: 3953.034 Thread 0x000000005c38d000 Exception <a 'java/net/SocketTimeoutException': Read timed out> (0x00000000f3944608) thrown at [C:\re\workspace\8-2-build-windows-amd64-cygwin\jdk8u60\4407\hotspot\src\share\vm\prims\jni.cpp, line 735]
Event: 3956.014 Thread 0x000000005e0a8800 Exception <a 'java/net/SocketTimeoutException': Read timed out> (0x00000000ef051a88) thrown at [C:\re\workspace\8-2-build-windows-amd64-cygwin\jdk8u60\4407\hotspot\src\share\vm\prims\jni.cpp, line 735]
...省略

从这里也可以看出,内部的10个异常事件中,基本都是socket超时,这也印证了刚刚的猜想。

看他源码

反编译,看到的核心代码:

的确是这么做的。

解决方案

最后,解决方案是使用线程池管理,控制最大线程数。如果请求过多,可使用队列缓冲。

hs_err_pid分析小工具

分析hs_err_pid文件是一个比较繁琐的工作,里面条条框框较多,因此,网上找到一个小工具,用AWT做的一个图形化分析小工具。

1
java -jar CrashAnalysis.jar hs_err_pid4256.log  //运行

效果图: