某java服务异常退出原因排查
ShaHimmel
8年前
<h2><strong>背景</strong></h2> <p>周日的时候，测试环境的一台java服务进程（以下简称A服务）异常退出。该情况在上周日就已经出现过一次，但是那次没有在意，只是以为是有人登陆了这台服务器将服务给停了。可是这次又出现了，说明这是一个问题，而不是偶然现象。咨询了运维小伙伴后，通过查阅/var/log/messages日志，可以看到是因为操作系统内存耗尽，触发了OOM killer，杀死了A服务。并且我们同时也看到了上周日也是因为触发了OOM killer，导致进程被OS杀死：</p> <pre> ...... Aug 5 21:11:25 iZ233ufr4soZ kernel: Out of memory: Kill process 18923 (java) score 558 or sacrifice child Aug 5 21:11:25 iZ233ufr4soZ kernel: Killed process 18923, UID 0, (java) total-vm:1638524kB, anon-rss:597908kB, file-rss:100kB </pre> <p>从日志中我们可以看到，A服务占用了操作系统大量的内存导致无法给其他应用程序分配内存。当时第一直觉是A服务发生了内存泄漏（后来证明第一直觉是错的）。关于内存泄露的文章网上有一大堆，简而言之就是 JVM里创建了大量的无法被垃圾回收但是不再被使用的对象 。在这里首先需要声明两点：</p> <ol> <li>内存泄露和内存溢出是两个不同的概念。内存泄露关心的是无用对象，内存泄漏最终会导致内存溢出。除了内存泄露，在瞬时读取大量数据至内存中也是会导致内存溢出的，比如数据库返回大量的对象，或者读取了一张很大的图片在内存中。</li> <li>垃圾收集算法普遍有两种，一种是引用计数（PHP），另一种是根搜索或者可达性分析。java采用的就是这种，具体算法网上文章一大堆，这里就不再赘述了。简而言之就是如果能够从根开始往下找到这个对象，那么这个对象就还有用，就不该回收。该方法可以有效解决循环引用。</li> </ol> <p>经典的、常见的内存泄漏的原因有以下几个方面：</p> <ol> <li>静态的集合类：由于这些变量的生命周期与应用程序保持一致，所以会导致这些类中的对象就算被手动置为null，也无法被释放。</li> <li>单例：同1，单例类的生命周期与应用程序也保持一致，如果单例类中也保持了某些对象，那么这些对象也是无法被回收的。</li> <li>各种连接、IO：这些操作都是十分消耗资源的，如果忘记了关闭，比如忘记关闭数据库连接，那么也是会发生内存泄漏的情况。</li> <li>threadlocal：由于threadlocal变量的生命周期与线程保持一致，当与线程池结合使用时，由于线程使用完毕后不会销毁，所以threadlocal变量可能也会出现泄漏的情况。</li> <li>其他：比如监听器，外部模块调用等。。</li> </ol> <h2><strong>Heap Dump</strong></h2> <p>大体上所有的内存泄露的原因都可以通过研究Heap Dump文件（堆转储）来解决。JVM可以通过jmap命令dump出当前的heap快照，通常后缀名为.hprof。JVM支持在OOM时，dump出当前的heap，便于开发人员分析为何出现了OOM。</p> <p>看了一下我们当前的启动脚本，发现没有添加导出HeapDump文件的参数。所以在 所有的启动语句中加上了 -XX:+HeapDumpOnOutOfMemoryError ，当JVM发生OOM时，可以自动地导出HeapDump文件。但是发现该参数没有起作用，经过仔细研究之后发现， 操作系统层级的OOM killer是不会触发HeapDumpOnOutOfMemoryError ，因为OOM killer直接杀死JVM进程，不会给你JVM任何机会，比如导出Heap，或者执行一些其他hook命令。但是当时并没有意识到这一点，只是接着往下走，也因此走了很多弯路。</p> <p>定位内存泄露的核心思路是 通过两份及以上的快照比对，查看是否有某些对象一直在增多，如果有的话，那么很可能发生了内存泄漏 。为了研究hprof文件，我们需要借助MAT（Eclipse Memory Analyzer Tool）。该工具的用法十分简单，照着网上的教程学一下就会。导入之后我们可以看到：</p> <p><img src="https://simg.open-open.com/show/fdc6fb98d6950e71caa0d42341e75034.png"></p> <p>MAT觉得可能是数据库连接发生了泄漏。然后点击Overview > Dominator Tree，并且按照class进行group by之后我们可以看到确实数据库连接占用了很多内存：</p> <p><img src="https://simg.open-open.com/show/5d69043b1cd140929f663b22d6338d1d.png"></p> <p>我的天，一共有180个。但是我马上冷静下来，确实是有180个，因为目前测试环境一共有6个库，A服务在启动的时候会默认每个库建立30个连接，一共180个。为了证实我的想法，点击右键，查看对象的所有GC路径：</p> <p><img src="https://simg.open-open.com/show/02c8cce22b7da3069bed4f1a9cb67b12.png"></p> <p>查看结果后，确实如此。由此可见数据库连接是十分消耗资源的，在测试环境上，我们默认启动的连接数应该要缩小，否则会占用大量的内存。</p> <p>那么是否发生了泄露呢，这时需要用到MAT的baseline比较功能，该功能是用来比较两个快照之间是否有对象数量和大小的变化。如果发生了内存泄漏，那么会存在一个对象的数量一直增多的情况。但是经过比较之后我发现，数据库连接只是占用了大量的内存，并没有出现异常增多的情况，并且其他对象类型也是一样，程序跑得十分稳定而又正常。</p> <p><img src="https://simg.open-open.com/show/1e9320e34cb8ed1e5f0600bdb5d132ca.png"></p> <h2><strong>JProfiler</strong></h2> <p>到了这一步，我开始怀疑其实A服务没有内存泄露的代码。那么如果没有内存泄露的话，为什么会占用这么高的内存呢？其实这个问题仔细想想，答案很简单，但是当时方向还是错了，我觉得还是有哪些地方可能出现了内存泄漏，所以上了profile工具。java世界中的profile工具首推JProfiler，网上可以下载破解版（付费的实在是太贵了）。通过JProfiler，我们可以实时监测JVM的一举一动。该工具十分好用，并且界面做的十分好看，推荐大家使用。PS：其实JProfiler包含了MAT的所有功能，只是MAT更加简洁，而且还免费。</p> <p>通过JProfiler可以看到，我们的内存波动十分正常，并没有出现内存占用越来越多的情况，否则蓝色的曲线应该是呈上升趋势。下图中，蓝色的线表示当前占用的内存，绿色的线表示当前heap的大小：</p> <p><img src="https://simg.open-open.com/show/aceac6c40a85fdbaf8c4382a56cb1caf.png"></p> <h2><strong>最后</strong></h2> <p>由此可见，A服务其实没有存在内存泄漏。回过头来看，其实我们的OOM发生在操作系统层，和我们平时遇到的JVM的OOM是不一样的。这里需要介绍一下OOM killer：操作系统在给应用程序分配内存时，采用的是over-commit策略，即无论应用需要多少内存，操作系统都会允许，即使超过了目前剩余的容量，操作系统依然允许。这是因为操作系统觉得大部分的应用程序并不会用满他自己声明的内存。但是还是可能会出现大家都用满了自己声明的内存的情况，这个时候操作系统如果不释放内存出来，很可能连自己都无法运行了，所以这个时候操作系统就会叫OOM killer过来，给所有的进程打分，选出得分最高者，直接kill掉。一般都是内存占用最高的进程被kill掉。</p> <p>那么A服务为什么会占用这么多内存呢？当我们排除了“内存泄露”这个原因，那么只可能是A服务确实占用了这么多内存。通过 java -XX:+PrintFlagsFinal -version | grep -iE 'HeapSize|PermSize|ThreadStackSize' ，我们可以看到A服务的测试机上的默认JVM配置：</p> <pre> uintx AdaptivePermSizeWeight = 20 {product} intx CompilerThreadStackSize = 0 {pd product} uintx ErgoHeapSizeLimit = 0 {product} uintx HeapSizePerGCThread = 87241520 {product} uintx InitialHeapSize := 16297600 {product} uintx LargePageHeapSizeThreshold = 134217728 {product} uintx MaxHeapSize := 522190848 {product} uintx MaxPermSize = 174063616 {pd product} uintx PermSize = 21757952 {pd product} intx ThreadStackSize = 1024 {pd product} intx VMThreadStackSize = 1024 {pd product} </pre> <p>我们可以看到，在这台内存仅有1G的服务器上，MaxHeapSize竟然达到了500兆。由于A服务的不断运行，迟早有一天会吃满整个HeapSize，由于JVM不会自动归还HeapSize，就算你实际使用的heap大小只有一点点，操作系统还是认为你占用了这么多的HeapSize。所以这就解释了为什么我们需要一周的时间才会发生这个场景，那是因为由初始的HeapSize达到MaxHeapSize需要长时间的运行以积累足够的对象触发JVM的Heap扩展策略。也解释了在每次进程消失的时间点，我们实际上没有做什么消耗资源的操作，但进程还是退出了，那是因为操作系统只认你占领的内存空间，并不会管你实际使用了多少空间。</p> <p>按照JVM默认的策略，MaxHeapSize默认是四分之一的内存空间，InitialHeapSize是64分之一的内存空间大小，这台机器之所以有500M的大小，会不会跟内存降过级有关（2G->1G），这就不得而知了。</p> <p>所以现在要复现问题也很简单。开启A服务，并且启动压力测试，让他瞬间吃满MaxHeapSize，然后再随便开启一个也占用较多资源的应用（比如Mysql），这个时候就会发现A服务又被杀死了，并且/var/log/messages中打出了相应的日志。</p> <p>具体地解决方案：</p> <ol> <li>测试环境默认创建的线程数以及连接数需要往小设，因为测试环境不会有这么多的并发。</li> <li>手动配置JVM的最大堆（-Xmx）和初始堆（-Xms）的大小，具体大小值需要根据实际情况而定，设置地太大容易被OOM killer杀掉，设置地太小容易发生十分频繁的GC操作。在测试环境中，可以尽量往小配置，避免其他应用影响。</li> <li>加上 -XX:+HeapDumpOnOutOfMemoryError ，便于在JVM发生OOM时，可以还原“事故现场”。</li> </ol> <p>PS：由于一个java应用是单进程程序，所以当OOM killer选择了java的时候，整个java世界就会瞬间崩塌，JVM无法做任何响应就退出了，无法做任何gracefully shutdown，也不会有任何日志文件写出。如果从这个方面来看的话，PHP的多进程思路是优于java应用的。</p> <h2><strong>总结</strong></h2> <h3><strong>查看日志</strong></h3> <p>当某一java应用程序意外退出时，先查看日志信息，具体的日志有以下几个：</p> <ol> <li>/var/log/messages*：查看系统内核日志，判断是否被OOM killer杀死。如果是的话，那么说明系统内存资源紧张。此时可以通过日志查看当时列出来的所有占用内存较多的进程，kill掉一些无关的进程节省内存空间。并且通过调小 -Xmx 参数，或者将自己纳入OOM killer的白名单，避免因为排名过高被意外杀死。</li> <li>./java_pid.hprof：查看heap dump信息。如果JVM启动时配置了 -XX:+HeapDumpOnOutOfMemoryError ，并且没有指定其他路径，那么可以在当前目录下找到hprof文件。利用MAT等其他工具进行分析，查看是哪些对象占用了较多的内存导致JVM无法继续分配内存。</li> <li>./hs_err_pid.log：查看JVM崩溃信息。比如应用程序当无法再申请到服务器资源，或者JNI调用错误的时候，就会出现JVM崩溃错误，那么默认在当前目录下可以找到hs_err_pid.log文件。</li> <li>/var/log/xxx/xxx.log：查看应用自身日志。某些情况可能是系统自身调用了System.exit函数，此时需要查看自身日志。</li> </ol> <h3><strong>定位问题</strong></h3> <p>通过查看日志之后，确定是由于内存溢出导致的，那么需要判断是否是因为内存泄露导致的。我们可以先分析JVM退出时dump出来的堆转储文件，若存在着大量数量异常多的无用对象，那么肯定是发生了内存泄露。</p> <p>定位内存泄露的思路十分简单，就是通过Jmap或者其他工具按照一定的时间间隔dump出heap，然后通过MAT或其他工具来进行比较分析。若发现有某个对象，随着时间增长在不停地变多，而该对象理应被GC回收，那么就是该对象发生了内存泄漏。此时我们可以查看该对象的GC root，找到引用该对象的根位置，从而定位问题。</p> <p>若觉得MAT不是很好用，还可以使用更加高级的JProfiler工具。</p> <h2><strong>其他</strong></h2> <p>综上所述，其实整个问题是一个参数配置的问题。参数配置的问题始终是一个难题。每一个参数的配置，最后组合在一起会形成质变的效果。深入了解每个模块可配置的参数的含义，多做压力测试，可以方便我们提前找到问题。</p> <h2><strong>参考资料</strong></h2> <ol> <li><a href="/misc/goto?guid=4959714148883611680" rel="external">jprofiler如何进行远程监控</a></li> <li><a href="/misc/goto?guid=4959632412803934719" rel="external">jvm相关参数</a></li> <li><a href="http://www.importnew.com/17153.html?hmsr=toutiao.io&utm_medium=toutiao.io&utm_source=toutiao.io" rel="external">诊断java的内存泄露</a></li> <li><a href="/misc/goto?guid=4959714149089662319" rel="external">MAT使用入门</a></li> <li><a href="/misc/goto?guid=4959714149171482499" rel="external">OOM killer</a></li> <li><a href="/misc/goto?guid=4959714149265336939" rel="external">Find out your jvm heap size</a></li> <li><a href="/misc/goto?guid=4959714149347092541" rel="external">深入研究JVM</a></li> <li><a href="/misc/goto?guid=4959714149432794803" rel="external">OOM未导出hprof文件</a></li> </ol> <p> </p> <p>来自：http://www.kissyu.org/2016/08/09/某java服务异常退出原因排查/</p> <p> </p>