JVM(二)故障分析和解决

Open Sayi opened this issue 7 years ago • 0 comments

应用的故障有时候会体现在JVM层面，大多数JVM的问题又是一个时间问题，不是很快能复现或者到某个时间点才发生，分析和解决这类问题就显得尤为重要，本文就从内存和线程两方面阐述问题解决思路以及介绍一些JDK提供的工具，关于JVM致命错误(System Crashes)及更多类型的故障解决，可以参见:

Java Platform, Standard Edition Troubleshooting Guide

内存泄漏Memory Leaks和内存溢出OutOfMemoryError

OutOfMemoryError的种类有很多，参考Understand the OutOfMemoryError Exception和OutOfMemoryError，通过上篇文章我们已经知道虚拟机运行时哪些数据区域会定义内存溢出，接下来我们就来看看如何解决这些区域的内存问题。

第一条：分析GC日志

当内存空间不够时，会触发GC，Minor GC是年轻代频繁的GC，当发生Full GC我们就需要重点关注了，通过GC日志我们可以清晰的看到每次GC的效果，那么 我们如何查看GC日志呢？

我们需要通过参数打开GC日志：

Options	说明
-Xloggc:gc.log	输出GC日志到文件gc.log
-XX:+PrintGCDetails	输出GC详细信息
-XX:+PrintGCDateStamps	输出GC时间戳

接下来我们写一段测试代码来触发FullGC，代码通过不断新增字符串的方式在堆内产生java.lang.OutOfMemoryError: Java heap space异常，由于GC日志根据选用的收集器不同，日志内容会有些许不一样的体现，这里我们使用CMS收集器配合ParNew收集器，命令行参数如下：

-Xloggc:gc.log  -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+UseConcMarkSweepGC

测试代码如下：

@Test
public void testGC() {
    String base = "hi";
    for (int i = 0; i < 100; i++) {
        String str = base + base;
        base = str;
    }
}

最后生成的gc.log文件行数比较多，我们重点是读懂MinorGC和FullGC信息，如下是年轻代的MinorGC：

[GC (Allocation Failure) 2018-12-04T11:16:47.601-0800: 5.797: [ParNew: 262144K->2K(295552K), 1.0766473 secs] 656148K->656152K(952228K), 1.0768043 secs] [Times: user=1.36 sys=0.24, real=1.07 secs]

可以通过下面这张图进行分解：

我们可以看到，在经过一次MinorGC后，堆的使用空间并未减少，我们再来看看FullGC：

[Full GC (Allocation Failure) 2018-12-04T11:16:50.203-0800: 8.399: [CMS: 525076K->525014K(707840K), 0.2031043 secs] 525076K->525014K(1014528K), [Metaspace: 4933K->4933K(1056768K)], 0.2035787 secs] [Times: user=0.13 sys=0.06, real=0.20 secs]

理解了MinorGC，FullGC的信息很好理解，我们还是看下面这张图来解读，可以看到老年代垃圾回收的效果并不理想：

至此，我们已经知道如何从GC信息中获取内存中各个区空间的变化以及哪个区可能会发生故障，这里推荐一款 在线分析GC日志 的网站：GC easy，通过上传gc文件可视化分析内存区域，我们将测试代码生成的文件上传到这个网站进行分析，很清楚的看到老年代在GC前后并没有多大变化。

我们也可以实时监控GC，比如可视化JvisualVM的Visual GC：

还可以通过命令行工具jstat查看gc，5125是进程id，3表示输出次数，100表示输出间隔：

$ jstat -gc 5125 100 3
 S0C    S1C    S0U    S1U      EC       EU        OC         OU       MC     MU    CCSC   CCSU   YGC     YGCT    FGC    FGCT     GCT   
 0.0   4096.0  0.0   4096.0 264192.0 16384.0   277504.0   230441.1  151744.0 138272.6 20216.0 16474.0     72    6.528   0      0.000    6.528
 0.0   4096.0  0.0   4096.0 264192.0 16384.0   277504.0   230441.1  151744.0 138272.6 20216.0 16474.0     72    6.528   0      0.000    6.528
 0.0   4096.0  0.0   4096.0 264192.0 16384.0   277504.0   230441.1  151744.0 138272.6 20216.0 16474.0     72    6.528   0      0.000    6.528

其中S表示survivor区，E表示eden区，O表示Old区，M表示方法区，后缀C表示当前大小，U表示当前使用大小，关于jstat会在下文详细介绍。

第二条：分析堆dump文件

堆dump文件(格式为.hprof)保存了java进程运行时刻的内存快照，当内存问题产生时，我们可以深入堆dump文件来查看到底是什么对象占用了内存。我们首先要考虑的是 怎么产生这个dump文件？

通过VM参数在内存溢出时自动生成堆dump文件：-XX:+HeapDumpOnOutOfMemoryError
通过可视化工具生成堆dump文件：比如JvisualVM的监视视图除了可以监控内存情况，还可以通过按钮生成dump文件
通过命令行工具jcmd生成堆dump文件，命令如下，其中38935是进程id，具体如何使用jcmd会在下文详细描述。

jcmd 38935 GC.heap_dump /Users/Sayi/pid38935.hprof

我们还是以上文的GC日志测试代码加上自动生成堆dump的参数，最终会生成文件java_pidXXXX.hprof文件，当我们获取到堆dump文件后，就可以进行分析了，这里推荐三种分析方法：

通过在线分析网站http://heaphero.io/，由于一般dump文件会比较大，所以上传会比较慢
通过Memory Analyzer(MAT)分析，这是一款基于Eclipse的Java Heap分析插件：http://www.eclipse.org/mat/
通过JvisualVM打开dump文件进行分析，提供了可视化查看堆内存的功能

我们先来看看JvisualVM，当我们打开dump文件后，在概览里面可以看到一些基础信息，同时可以在右侧视图中直接查找大对象：

可以点开类视图，查看具体哪个类的实例数和大过大，从下图可以看到，字节数组占用了99.9%的空间：

点击具体的某个类可以计入实例数视图，可以看到具体存储的内容是哪些，根据存储内容进而可以知道是在哪块业务里面导致了内存问题：

MAT和JvisualVM虽然界面操作有差异，但是功能其实很相似，我们可以找到占用内存比较大的对象以及这些对象的引用关系，MAT里面的Diminator Tree视图可以查看大对象：

第三条：分析MetaSpace内存

MetaSpac区主要存储一些类信息，我们可以通过限制MetaSpace区大小，然后加载很多类产生java.lang.OutOfMemoryError: Metaspace异常，这里的测试代码使用不同的URLClassLoader去加载一个字节码文件达到相同的效果:

@Test
public void testMetaSpace() throws Exception {
    // -XX:MetaspaceSize=8m -XX:MaxMetaspaceSize=8m
    List<ClassLoader> classLoaders = new ArrayList<ClassLoader>();
    while (true) {
        URLClassLoader classLoader = new URLClassLoader(
                new URL[] { new File("./").toURI().toURL() });
        Class<?> loadClass = classLoader.loadClass("JVMTest");
        classLoaders.add(classLoader);
        System.out.println(classLoaders.size() + "-" + loadClass.getClassLoader());
    }
}

我们可以将堆dump文件通过MAT打开进行分析，通过duplicate_classes可以看到哪些类被多个加载器加载了：

我们再来看一种情况，使用cglib生成很多代理类信息也会导致MetaSpace区内存溢出：

@Test
public void testMetaSpace2() throws Exception {
    // -XX:MetaspaceSize=8m -XX:MaxMetaspaceSize=8m
    for (int i = 0;; i++) {
        Enhancer enhancer = new Enhancer();
        enhancer.setSuperclass(List.class);
        enhancer.setUseCache(false);
        enhancer.setCallback(new net.sf.cglib.proxy.MethodInterceptor() {
            @Override
            public Object intercept(Object obj, Method method, Object[] args, MethodProxy proxy)
                    throws Throwable {
                return null;
            }
        });
        Object create = enhancer.create();
    }
}

这个时候通过MAT打开dump文件duplicate_classes视图是空的，因为这些都是代理类，不是重复类，那么我们该怎么分析这个问题呢？

我们可以从堆dump文件中找到实例数很多的类(并不一定是最多的几个实例数类，因为业务实例可能真的有那么多)，进而可以分析这些实例的具体类型，查找是什么Class信息加载过多，通过MAT或者JvisualVM可以看到net.sf.cglib.proxy.MethodProxy有很多实例，这些实例都被不同的代理类使用。

MAT还提供了报表的功能，通过Leak Suspects能查看可能的内存问题，这也是一种方法：

类加载信息还可以通过命令行进行分析，jcmd 33984 GC.class_stats或者jmap -clstats 26240，暂时我还没有使用到，这里就不介绍了。

进程挂起和循坏Process Hangs and Loops

应用程序的问题有时候并非是内存问题，可能由于某些原因导致进程挂起或无限循坏，比如大量线程阻塞在一个超时的请求中无法释放，我们需要对某个时刻所有的线程进行分析，找到出问题的线程执行的代码。还是老问题，如何获取某个Java进程的线程dump文件(后缀名.tdump)？

1.jcmd命令行工具，其中38935是进程id，Thread.print是命令

jcmd 38935 Thread.print > /Users/Sayi/pid38935.tdump

2.jstack命令行工具

jstack 38935 > /Users/Sayi/pid50455.tdump

3.JvisualVM可视化工具：通过线程视图可以dump线程信息

还有一些更多的获取线程dump方式，这篇文章介绍了8种方式HOW TO TAKE THREAD DUMPS?。

获取到线程dump文件后，它本身是可以阅读的，内容大概如下：

"pool-1-thread-9" #18 prio=5 os_prio=31 tid=0x00007f937096c000 nid=0x5f03 runnable [0x00007000052f3000]
   java.lang.Thread.State: RUNNABLE
        at java.net.PlainSocketImpl.socketConnect(Native Method)
        at java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:350)
        - locked <0x00000007aadf7c28> (a java.net.SocksSocketImpl)
        at java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:206)
        at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:188)
        at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392)
        at java.net.Socket.connect(Socket.java:589)
        at org.apache.http.conn.socket.PlainConnectionSocketFactory.connectSocket(PlainConnectionSocketFactory.java:75)
        at org.apache.http.impl.conn.DefaultHttpClientConnectionOperator.connect(DefaultHttpClientConnectionOperator.java:142)
        at org.apache.http.impl.conn.PoolingHttpClientConnectionManager.connect(PoolingHttpClientConnectionManager.java:359)
        at org.apache.http.impl.execchain.MainClientExec.establishRoute(MainClientExec.java:381)
        at org.apache.http.impl.execchain.MainClientExec.execute(MainClientExec.java:237)
        at org.apache.http.impl.execchain.ProtocolExec.execute(ProtocolExec.java:185)
        at org.apache.http.impl.execchain.RetryExec.execute(RetryExec.java:89)
        at org.apache.http.impl.execchain.RedirectExec.execute(RedirectExec.java:111)
        at org.apache.http.impl.client.InternalHttpClient.doExecute(InternalHttpClient.java:185)
        at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:83)
        at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:108)
        at com.deepoove.java8.JVMOptionTest.lambda$0(JVMOptionTest.java:84)
        at com.deepoove.java8.JVMOptionTest$$Lambda$1/1579572132.run(Unknown Source)
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
        at java.util.concurrent.FutureTask.run(FutureTask.java:266)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
        at java.lang.Thread.run(Thread.java:748)

pool-1-thread-9是线程名称，prio是线程优先级，tid是线程id，nid是线程的nativeId，RUNNABLE表示运行状态。我们需要通过观察dump文件中的线程，或者观察比较相隔一定时间间隔的dump文件来找到可能出问题的线程，比如死锁、线程执行缓慢等。推荐一个在线的线程tdump分析工具：http://fastthread.io，可以总结所有线程的状态和信息，同时这个工具还可以分析Hs_err_pid错误。

我们来试想一个问题，如何快速从线程dump文件找到最繁忙的线程?

首先我们可以通过top命令查看某个进程内部的线程信息，其中pid是你的java进程id：

top -H -p <pid>

在top线程视图中的第一列PID就是这些线程的十进制id，转化为16进制后的值对应线程dump文件中nid的字段，进而可以从线程dump文件中获得这个线程的栈信息。

Java故障监控工具

JDK提供了一些故障监控工具，便于我们处理一些虚拟机相关层面的问，接下来我们主要介绍一些常用工具，详细信息参见官网：Java Troubleshooting, Profiling, Monitoring and Management Tools

jcmd

jcmd是一个非常强大的诊断命令，是jps、jinfo、jmap的功能集合，现在它是官方推荐的命令行工具。它的基本使用方式是通过发送command请求给运行的虚拟机：

jcmd <pid> <command>

查看当前运行的Java进程ID

$ jcmd
17416 org.apache.catalina.startup.Bootstrap start
4990 sun.tools.jcmd.JCmd -l

我们也可以通过ps linux命令查找java进程。

查看具体某个进程支持的command命令

$ jcmd 17416 help
17416:
The following commands are available:
JFR.stop
JFR.start
JFR.dump
JFR.check
VM.native_memory
VM.check_commercial_features
VM.unlock_commercial_features
ManagementAgent.stop
ManagementAgent.start_local
ManagementAgent.start
GC.rotate_log
Thread.print
GC.class_stats
GC.class_histogram
GC.heap_dump
GC.run_finalization
GC.run
VM.uptime
VM.flags
VM.system_properties
VM.command_line
VM.version
help

通过help我们可以看到很多可用的command，其中有些非常有用，具体每个命令如何使用，可以通过jcmd <pid> help <command>阅读。

查看VM参数

$ jcmd 5125 VM.command_line
5125:
VM Arguments:
jvm_args: -Dosgi.requiredJavaVersion=1.8 [email protected]/eclipse-workspace -XX:+UseG1GC -XX:+UseStringDeduplication --add-modules=ALL-SYSTEM -XstartOnFirstThread -Dorg.eclipse.swt.internal.carbon.smallFonts -Dosgi.requiredJavaVersion=1.8 -Dosgi.dataAreaRequiresExplicitInit=true -Xms256m -Xmx1024m --add-modules=ALL-SYSTEM -Xdock:icon=../Resources/Eclipse.icns -XstartOnFirstThread -Dorg.eclipse.swt.internal.carbon.smallFonts -Dosgi.requiredJavaVersion=1.8 [email protected]/eclipse-workspace -XX:+UseG1GC -XX:+UseStringDeduplication -XstartOnFirstThread -Dorg.eclipse.swt.internal.carbon.smallFonts -Dosgi.requiredJavaVersion=1.8 -Dosgi.dataAreaRequiresExplicitInit=true -Xms256m -Xmx1024m -Xdock:icon=../Resources/Eclipse.icns -XstartOnFirstThread -Dorg.eclipse.swt.internal.carbon.smallFonts 
java_command: <unknown>
java_class_path (initial): /Applications/Eclipse.app/Contents/MacOS//../Eclipse/plugins/org.eclipse.equinox.launcher_1.5.100.v20180827-1352.jar
Launcher Type: generic

这个命令显示我Mac上运行的Eclipse的虚拟机参数，可以看到使用的垃圾回收策略是G1。

查看系统属性

$ jcmd 17416 VM.system_properties
17416:
#Tue Dec 04 23:49:00 CST 2018
java.vendor=Oracle Corporation
sun.java.launcher=SUN_STANDARD
catalina.base=/home/Sayi/projects/demo/.base
sun.management.compiler=HotSpot 64-Bit Tiered Compilers
sun.nio.ch.bugLevel=
catalina.useNaming=true
os.name=Linux
java.vm.specification.vendor=Oracle Corporation
java.runtime.version=1.8.0_77-b03
user.name=Sayi
shared.loader=
tomcat.util.buf.StringCache.byte.enabled=true
user.language=en
java.naming.factory.initial=org.apache.naming.java.javaURLContextFactory
APP_HOME=/home/souche/projects/cupid
java.version=1.8.0_77
// 略

生成堆dump文件

$ jcmd 38935 GC.heap_dump /Users/Sayi/pid38935.hprof
38935:
Heap dump file created

生成线程dump文件

$ jcmd 38935 Thread.print > /Users/Sayi/pid38935.tdump

查看堆内存中每个类的图表

$ jcmd 5125 GC.class_histogram > class.histogram

这个命令可以 实时查看堆中内存类的情况。

查看类的meta data 信息

$ jcmd 33984 GC.class_stats

这条命令需要开启VM参数-XX:+UnlockDiagnosticVMOptions，提供了类加载相关的信息，在分析metaspace区类信息非常有用。

jstat

这是一个非常强大的监控工具，它的基本用法如下：

jstat -<option>  <pid> [<interval> [<count>]]

因为是实时监控，所有有了按一定时间间隔输出的参数，interval表示时间间隔，count表示输出次数。option是一些可选命令，每个命令有其内在的含义，我们通过jstat -options查看所有可用选项：

$ jstat -options
-class
-compiler
-gc
-gccapacity
-gccause
-gcmetacapacity
-gcnew
-gcnewcapacity
-gcold
-gcoldcapacity
-gcutil
-printcompilation

监控类加载器统计数据

$ jstat -class 5125 500 3
Loaded  Bytes  Unloaded  Bytes     Time   
 39656 74207.2      409   619.4      93.50
 39656 74207.2      409   619.4      93.50
 39656 74207.2      409   619.4      93.50

监控GC数据总结

$ jstat -gcutil 5125 500 3
  S0     S1     E      O      M     CCS    YGC     YGCT    FGC    FGCT     GCT   
  0.00 100.00  12.50  31.79  91.54  83.16    163   23.747     2   38.079   61.825
  0.00 100.00  12.50  31.79  91.54  83.16    163   23.747     2   38.079   61.825
  0.00 100.00  12.50  31.79  91.54  83.16    163   23.747     2   38.079   61.825

这里给出所有可选项的含义，摘自Java Tools Reference: jstat：

option	含义
class	Displays statistics about the behavior of the class loader.
compiler	Displays statistics about the behavior of the Java HotSpot VM Just-in-Time compiler.
gc	Displays statistics about the behavior of the garbage collected heap.
gccapacity	Displays statistics about the capacities of the generations and their corresponding spaces.
gccause	Displays a summary about garbage collection statistics (same as -gcutil)
gcnew	Displays statistics of the behavior of the new generation.
gcnewcapacity	Displays statistics about the sizes of the new generations and its corresponding spaces.
gcold	Displays statistics about the behavior of the old generation and metaspace statistics.
gcoldcapacity	Displays statistics about the sizes of the old generation.
gcmetacapacity	Displays statistics about the sizes of the metaspace.
gcutil	Displays a summary about garbage collection statistics.
printcompilation	Displays Java HotSpot VM compilation method statistics.

jstack

查看线程信息，使用方法为：

jstack [-l] <pid>

其中-l参数会打印更多关于锁相关的信息。

JvisualVM

这是一个可视化工具，自称为“All-in-One Java Troubleshooting Tool”，基本上命令行实现的故障诊断和监控功能，都可以可视化呈现。

它可以用来实时监控Java进程信息，下面这张图是监视视图，可以查看内存、CPU、类和线程的情况，同时右上角提供了生成堆dump的功能。

线程视图展示了当前进程运行的所有线程信息，右上角也提供了生成线程dump功能。

JvisualVM还可以通过插件方式进行扩展，安装VisualGC后可以实时查看GC信息。

JvisualVM同时也是一个分析工具，可以加载堆dump和线程tdump文件进行分析，上文在堆内存分析中已经介绍过如何使用。

总结

当我们了解了常见故障和故障的分析方法，接下来就需要我们在实践中去反复磨炼自己的技能了，关于JVM故障的分析和处理，相信所有人终有一天会有【拨开云雾见天日】的感觉。

Dec 04 '18 16:12 Sayi

JVM(二)故障分析和解决

内存泄漏Memory Leaks和内存溢出OutOfMemoryError

第一条：分析GC日志

第二条：分析堆dump文件

第三条：分析MetaSpace内存

进程挂起和循坏Process Hangs and Loops

Java故障监控工具

jcmd

jstat

jstack

JvisualVM

更多工具

总结