深入分析javaweb技术内幕之JVM内存管理（二）

8.7内存问题分析

8.7.1GC日志分析

有时候我们可能并不知道何时会发生内存溢出，但是当溢出已经发生时我们却并不知道原因，所以在JVM启动时就加上一些参数来控制，当JVM出问题时能几下一些当时的情况。还有就是记录下来的GC的日志，我们可以观察GC的频度以及每次GC都回收了哪些内存。

GC的日志输出如下参数。

-verbose：gc，可以辅助输出一些详细的GC信息。

-XX：+PrintGCDetails，输出GC的详细信息。

-XX：+PrintGCApplicationStoppedTime，输出GC造成应用程序暂停的时间。

-XX：+PrintGCDateStamps，GC发生的时间信息。

-XX：+PrintHeapAtGC，在GC前后输出堆中各个区域的大小。

-Xloggc：[file],将GC信息输出到单独的文件中。

除CMS的日志与其他GC的日志差别较大外，它们都可以抽象成如下格式：

其中说明如下：

• <collector>GC表示收集器的名称。
• <starting occupancy1>表示Young区在GC前占用的内存。
• <ending occupancy1>表示Young区在GC后占用的内存。
• <pause time1>表示Young区局部收集时JVM暂停处理的时间。
• <starting occupancy2>表示JVM Heap在GC前占用的内存。
• <starting occupancy2>表示JVM Heap在GC后占用的内存。
• <pause time2>表示在GC过程中JVM暂停处理的总时间。

可以根据日志来判断是否有内存在泄漏，如果<ending occupancy1>-<starting occupancy1>=<ending occupancy2>-<staring occupancy2>，则表明这次GC对象100%被回收，没有对象进入Old区或者metadataspace区。

除去日志文件分析外，还可以直接通过JVM自带的一些工具分析，如jstat，使用格式为jstat -gcutil[pid][intervel][count]。

8.7.2堆快照文件分析

可通过命令jmap -dump：format=b，file=[filename][pid]来记录下堆的内存快照，然后利用第三方工具（如mat）来分析真个Heap对象关联情况。

如果内存耗尽那么可能导致JVM直接垮掉，可以通过参数：-XX：+HeapDumpOnOutOfMemmoryError来配置当内存耗尽时记录下内存快照，可以通过-XX：HeapDumpPath来指定文件的路径，这个文件的命名格式如java_[pid].hprof。

8.7.3JVM Crash日志分析

JVM有时也会因为一些原因而导致直接垮掉，因为JVM本身也是一个正在运行的程序，这个程序本身也会有很多情况直接出问题，如JVM本身也有一些Bug，这些Bug可能会导致JVM异常退出。JVM退出一般是在工作目录下产生一个日志文件，也可以ton通过JVM参数来设定。如-XX：ErrorFile=/tmp/log/hs_error_%p.log。

下面是一个日志文件：

2.GIGSEGV

JVM正在执行本地JNI的代码，出这种错误很可能是第三方的本地库有问题，可以通过gbd和core文件来分析出错原因。

3.EXCEPTION_STACK_OVERFLOW

这个是栈溢出的错误，注意JVM在执行java线程时出现的栈溢出通常不会导致JVM退出，而是抛出java.lang.*Error，但是在java虚拟机中，Java的代码和本地C或C++代码共用相同的栈，这时如果出现栈溢出的话，就有可能直接导致JVM退出。建议将JVM的栈尺寸调大，主要涉及两个参数，-Xss和-XX：StackShadowPages=n。

日志文件的Thread部分的信息对我们排查这个问题的原因最有帮助，这部分有两个关系信息，包括Machine Instructions和Thread Stack。Machine Instructions是当前系统执行的机器指令，是16进制的。我们可以将它转成指令，通过udis86工具来转换，该工具可以在http://udis86.sourceforge.net/下载，安装在Linux中，将上面的16进制数字复制到命令行中用如下方式执行转换：

可以得到汇编指令，由于是64位机器，所以是udcli-64-x，如果是32机器，则改成udcli-32-x，可以通过这个指令来判断当前正在执行什么指令而导致了垮掉。例如，如果当前爱访问寄存器地址，那么这个地址是否合法，以及如果是除法指令，操作数是否合法等。

而Stack信息最直接，可以帮助我们看到到底是哪个库的哪行代码出错，如在上面的错误信息中显示的是由于执行Oracle的Java驱动程序引起出错的。我们还可以通过生成的core文件来更详细地看出是执行到哪行代码出错的，如下所示：

通过每个分区当前所使用的空间大小，尤其是Old区的空间是否已经满了，可以判断出当前的GC是否正常。

还有一个信息也比较有价值，那就是当前JVM的启动参数，设置的堆大小和使用的GC方式等都可以从这里看出。

最后一部分是System信息，这部分主要记录了当前操作系统的状态信息，如操作系统的CPU信息和内存情况等。

的某些属性指向一个对象，那么所指向的哪个对象的大小就计算在Retained Heap中。

图8-6中SkechCompileContext对象持有一个Map集合，这个Map集合所占用的空间很大，仔细查看后发现这个Map持有一个DO对象，这个对象的确是一个大队向，它的大小并没有超出我们的预期，仔细查看其他集合，没有发现所持有对象有什么不对的地方。但是仔细计算整个对象集合的大小发现，虽然所有的对象都是应该存在的，但是比我们计算的正常大小多了将近一倍，于是我们想到可能是持有了两份同样的对象。

按照这个思路仔细搜索这个Map集合中的对象的数值果然发现同样一个数值有两个不同的DO对象对应，但是为什么有两个DO对象呢？正常情况应该单一啊，怎么会产生两份DO对象？后面仔细检查这个DO对象的业务逻辑，原来是这个DO要在每天凌晨两单更新一次，更新后老对象会自动释放，但是我们这个新引擎是要保存这些对象，以便于做编译优化，不能及时释放这个更新后的老对象，所以导致这个大对象在内存中保存了两份。

8.9实例2

这个例子和前面介绍的CMS GC回收方式的一个JVM的Bug相关，淘宝的某应用在某天突然导致线上部分机器报警，Java的内存使用非常严重，达到了6GB，超过了平时的4GB，而且有几台机器进行一段时间后导致OOM、JVM退出。但是相关人员的第一反应是重启部分机器，保留几台有问题的机器来寻找原因。

观察重启后的机器，发现应用回复正常，但是发现JVM进程占用的内存一直在增长，可以大体推断出是JVM有内存泄漏。然后检查最近是否有系统改动，是否是Java代码问题导致了内存泄漏。检查后发现最近一周Java代码改动很少，而且也没有发现有内存泄漏问题。

同时检查GC日志，发现有问题的机器Full GC没有异常，甚至Full GC比平时还少，CMS GC也很少。从日志中没有发现可能有内存问题。

为了进一步确认GC是否正常，我们找出JVM的Heap，用MAT分析堆文件，堆的使用情况如图8-7所示。

可以看出，整个Heap只有不到1GB的空间，而且从Leak Suspects给出的报告中可以看到占有最大空间的对象是一个DO对象，如图8-8所示。

我们于是想到了可能是堆外内存分配的内存有泄漏，从前面的分析中我们已经知道，JVM除了堆需要内存外还有很多方面也需要在运行时使用内存，如JVM本身JIT编译需要内存，JVM的栈也需要内存，JNI调用本地代码也需要内存，还有NIO方式也会使用Direct Buffer来申请内存。

从这些因素中我们推断可能是Direct Buffer导致的，因为在上次发布中引入过一个Apache的Mina包，在这个包中肯定使用了Direct Buffer，但是为什么Direct Buffer没有正常回收呢？很奇怪。

这时想到了可能是JVM的一个Bug，详见http://bugs.sun.com/bugdatabase/view_bug.do?bug_id=6919638。外部调用了System.gc，且设置了-XX：+DisableExplicitGC，所以导致System.gc()变成了空调用，而应用GC却很少，这里的GC包括CMS GC和Full GC。所以Direct Buffer对象没有被及时回收，相应的native memory不能被释放。为了验证这一点，相关人员还写了一个工具来检查当前JVM中NIO direct memory的使用情况，如下所示：

8.10 实例3

下面再介绍一个NIO direct memory发生内存泄漏的例子。

JVM的配置参数如下：

想使用Oprofile热点分析工具分析当前系统执行的热点代码，如果是当前的native memory有泄漏，那么肯定会出现分配内存的代码是热点的情况，用Oprofile分析的CPU的消耗情况如图8-15所示。

如图8-15所示，和预想的情况并不吻合，一时找不到更好的办法，于是使用土办法，一部分、一部分地去掉功能模块，看看到底是哪个模块导致的内存泄漏，进一步缩小范围。

通过删除可能会出问题的几个模块后，最后确定是调用mina框架给varnish发送失败请求时导致的，而且发送的请求数频率越高内存泄漏越严重，但是mina框架没有使用native memory的地方，于是又陷入僵局。

使用Perftools来分析JVM的native Memory分配情况，通过Perftools得到的分析结果如图8-16所示。