背景

上周末，我一个朋友来到我家，抛给我一个“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记录。
PSYoungGen与ParOldGen可知道，垃圾回收使用的是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  //运行

效果图：

更多文章，请关注：开猿笔记