教你如何成為Java的OOM Killer

作者：李艷鵬 2017-07-07 16:30:37

雖然事隔半年，當(dāng)時(shí)排查線(xiàn)上OOM事故的過(guò)程記憶猶新，每一個(gè)步驟都?xì)v歷在目，感謝業(yè)務(wù)組、系統(tǒng)部、壓測(cè)組、監(jiān)控與應(yīng)急部對(duì)架構(gòu)組的強(qiáng)力支持，得以讓這個(gè)Java內(nèi)存問(wèn)題水落石出，經(jīng)過(guò)半年多的全面的應(yīng)用日志切割方式的改造，現(xiàn)在基本沒(méi)有OOM的問(wèn)題了，線(xiàn)上服務(wù)運(yùn)行非常健康，對(duì)可用性的保障起到了很大的作用，如果你在經(jīng)歷OOM，讀了這個(gè)文章會(huì)有很大的啟發(fā)。

[[196172]]

前言

Become OOM Killer

我們都知道JVM的內(nèi)存管理是自動(dòng)化的，Java語(yǔ)言的程序指針也不需要開(kāi)發(fā)人員手工釋放，JVM的GC會(huì)自動(dòng)的進(jìn)行回收，但是，如果編程不當(dāng)，JVM仍然會(huì)發(fā)生內(nèi)存泄露，導(dǎo)致Java程序產(chǎn)生了OutOfMemoryError(OOM)錯(cuò)誤。

產(chǎn)生OutOfMemoryError錯(cuò)誤的原因包括：

java.lang.OutOfMemoryError: Java heap space
java.lang.OutOfMemoryError: PermGen space及其解決方法
java.lang.OutOfMemoryError: unable to create new native thread
java.lang.OutOfMemoryError：GC overhead limit exceeded

對(duì)于第1種異常，表示Java堆空間不夠，當(dāng)應(yīng)用程序申請(qǐng)更多的內(nèi)存，而Java堆內(nèi)存已經(jīng)無(wú)法滿(mǎn)足應(yīng)用程序?qū)?nèi)存的需要，將拋出這種異常。

對(duì)于第2種異常，表示Java永久帶(方法區(qū))空間不夠，永久帶用于存放類(lèi)的字節(jié)碼和長(zhǎng)常量池，類(lèi)的字節(jié)碼加載后存放在這個(gè)區(qū)域，這和存放對(duì)象實(shí)例的堆區(qū)是不同的，大多數(shù)JVM的實(shí)現(xiàn)都不會(huì)對(duì)永久帶進(jìn)行垃圾回收，因此，只要類(lèi)加載的過(guò)多就會(huì)出現(xiàn)這個(gè)問(wèn)題。一般的應(yīng)用程序都不會(huì)產(chǎn)生這個(gè)錯(cuò)誤，然而，對(duì)于Web服務(wù)器來(lái)講，會(huì)產(chǎn)生有大量的JSP，JSP在運(yùn)行時(shí)被動(dòng)態(tài)的編譯成Java Servlet類(lèi)，然后加載到方法區(qū)，因此，太多的JSP的Web工程可能產(chǎn)生這個(gè)異常。

對(duì)于第3種異常，本質(zhì)原因是創(chuàng)建了太多的線(xiàn)程，而能創(chuàng)建的線(xiàn)程數(shù)是有限制的，導(dǎo)致了這種異常的發(fā)生。

對(duì)于第4種異常，是在并行或者并發(fā)回收器在GC回收時(shí)間過(guò)長(zhǎng)、超過(guò)98%的時(shí)間用來(lái)做GC并且回收了不到2%的堆內(nèi)存，然后拋出這種異常進(jìn)行提前預(yù)警，用來(lái)避免內(nèi)存過(guò)小造成應(yīng)用不能正常工作。

下面兩個(gè)異常與OOM有關(guān)系，但是，又沒(méi)有絕對(duì)關(guān)系。

java.lang.StackOverflowError ...
java.net.SocketException: Too many open files

對(duì)于第1種異常，是JVM的線(xiàn)程由于遞歸或者方法調(diào)用層次太多，占滿(mǎn)了線(xiàn)程堆棧而導(dǎo)致的，線(xiàn)程堆棧默認(rèn)大小為1M。

對(duì)于第2種異常，是由于系統(tǒng)對(duì)文件句柄的使用是有限制的，而某個(gè)應(yīng)用程序使用的文件句柄超過(guò)了這個(gè)限制，就會(huì)導(dǎo)致這個(gè)問(wèn)題。

上面介紹了OOM相關(guān)的基礎(chǔ)知識(shí)，接下來(lái)我們開(kāi)始講述筆者經(jīng)歷的一次OOM問(wèn)題的定位和解決的過(guò)程。

1. 產(chǎn)生問(wèn)題的現(xiàn)象

在某一段時(shí)間內(nèi)，我們發(fā)現(xiàn)不同的業(yè)務(wù)服務(wù)開(kāi)始偶發(fā)的報(bào)OOM的異常，有的時(shí)候是白天發(fā)生，有的時(shí)候是晚上發(fā)生，有的時(shí)候是基礎(chǔ)服務(wù)A發(fā)生，有的時(shí)候是上層服務(wù)B發(fā)生，有的時(shí)候是上層服務(wù)C發(fā)生，有的時(shí)候是下層服務(wù)D發(fā)生，絲毫看不到一點(diǎn)規(guī)律。

產(chǎn)生問(wèn)題的異常如下：

Caused by: java.lang.OutOfMemoryError: unable to create new native thread at java.lang.Thread.start0(Native Method) 
at java.lang.Thread.start(Thread.java:597) 
at java.util.Timer.<init>(Timer.java:154)

2. 解決問(wèn)題的思路和過(guò)程

經(jīng)過(guò)細(xì)心觀察發(fā)現(xiàn)，產(chǎn)生問(wèn)題雖然在不同的時(shí)間發(fā)生在不同的服務(wù)池，但是，晚上0點(diǎn)發(fā)生的時(shí)候概率較大，也有其他時(shí)間偶發(fā)，但是都在整點(diǎn)。

這個(gè)規(guī)律很重要，雖然不是一個(gè)時(shí)間，但是基本都在整點(diǎn)左右發(fā)生，并且晚上0點(diǎn)居多。從這個(gè)角度思考，整點(diǎn)或者0點(diǎn)系統(tǒng)是否有定時(shí)，與出問(wèn)題的每個(gè)業(yè)務(wù)系統(tǒng)技術(shù)負(fù)責(zé)人核實(shí)，0點(diǎn)沒(méi)有定時(shí)任務(wù)，其他時(shí)間的整點(diǎn)有定時(shí)任務(wù)，但是與發(fā)生問(wèn)題的時(shí)間不吻合，這個(gè)思路行不通。

到現(xiàn)在為止，從現(xiàn)象的規(guī)律上我們已經(jīng)沒(méi)法繼續(xù)分析下去了，那我們回顧一下錯(cuò)誤本身：

java.lang.OutOfMemoryError: unable to create new native thread

顧名思義，錯(cuò)誤產(chǎn)生的原因就是應(yīng)用不能創(chuàng)建線(xiàn)程了，但是，應(yīng)用還需要?jiǎng)?chuàng)建線(xiàn)程。為什么程序不能創(chuàng)建線(xiàn)程呢?

有兩個(gè)具體原因造成這個(gè)異常:

由于線(xiàn)程使用的資源過(guò)多，操作系統(tǒng)已經(jīng)不能再提供給應(yīng)用資源了。
操作系統(tǒng)設(shè)置了應(yīng)用創(chuàng)建線(xiàn)程的最大數(shù)量，并且已經(jīng)達(dá)到了最大允許數(shù)量。

上面第1條資源指的是內(nèi)存，而第2條中，在Linux下線(xiàn)程使用輕量級(jí)進(jìn)程實(shí)現(xiàn)的，因此線(xiàn)程的最大數(shù)量也是操作系統(tǒng)允許的進(jìn)程的最大數(shù)量。

內(nèi)存計(jì)算

操作系統(tǒng)中的最大可用內(nèi)存除去操作系統(tǒng)本身使用的部分，剩下的都可以為某一個(gè)進(jìn)程服務(wù)，在JVM進(jìn)程中，內(nèi)存又被分為堆、本地內(nèi)存和棧等三大塊，Java堆是JVM自動(dòng)管理的內(nèi)存，應(yīng)用的對(duì)象的創(chuàng)建和銷(xiāo)毀、類(lèi)的裝載等都發(fā)生在這里，本地內(nèi)存是Java應(yīng)用使用的一種特殊內(nèi)存，JVM并不直接管理其生命周期，每個(gè)線(xiàn)程也會(huì)有一個(gè)棧，是用來(lái)存儲(chǔ)線(xiàn)程工作過(guò)程中產(chǎn)生的方法局部變量、方法參數(shù)和返回值的，每個(gè)線(xiàn)程對(duì)應(yīng)的棧的默認(rèn)大小為1M。

Linux和JVM的內(nèi)存管理示意圖如下：

內(nèi)存結(jié)構(gòu)模型

因此，從內(nèi)存角度來(lái)看創(chuàng)建線(xiàn)程需要內(nèi)存空間，如果JVM進(jìn)程正當(dāng)一個(gè)應(yīng)用創(chuàng)建線(xiàn)程，而操作系統(tǒng)沒(méi)有剩余的內(nèi)存分配給此JVM進(jìn)程，則會(huì)拋出問(wèn)題中的OOM異常：unable to create new native thread。

如下公式可以用來(lái)從內(nèi)存角度計(jì)算允許創(chuàng)建的最大線(xiàn)程數(shù)：

最大線(xiàn)程數(shù) = (操作系統(tǒng)最大可用內(nèi)存 - JVM內(nèi)存 - 操作系統(tǒng)預(yù)留內(nèi)存)/ 線(xiàn)程棧大小

根據(jù)這個(gè)公式，我們可以通過(guò)剩余內(nèi)存計(jì)算可以創(chuàng)建線(xiàn)程的數(shù)量。

下面是問(wèn)題出現(xiàn)的時(shí)候，從生產(chǎn)機(jī)器上執(zhí)行前面小節(jié)介紹的Linux命令free的輸出：

free -m >> /tmp/free.log 
             total       used       free     shared    buffers     cached 
Mem:          7872       7163        709          0         31       3807 
-/+ buffers/cache:       3324       4547 
Swap:         4095        173       3922 
Tue Jul 5 00:27:51 CST 2016

從上面輸出可以得出，生產(chǎn)機(jī)器8G內(nèi)存，使用了7G，剩余700M可用，其中操作系統(tǒng)cache使用3.8G。操作系統(tǒng)cache使用的3.8G是用來(lái)緩存IO數(shù)據(jù)的，如果進(jìn)程內(nèi)存不夠用，這些內(nèi)存是可以釋放出來(lái)優(yōu)先分配給進(jìn)程使用。然而，我們暫時(shí)并不需要考慮這塊內(nèi)存，剩余的700M空間完全可以繼續(xù)用來(lái)創(chuàng)建線(xiàn)程數(shù)：

700M / 1M = 700個(gè)線(xiàn)程

因此，根據(jù)內(nèi)存可用計(jì)算，當(dāng)OOM異常：unable to create new native thread問(wèn)題發(fā)生的時(shí)候，還有700M可用內(nèi)存，可以創(chuàng)建700個(gè)線(xiàn)程。

到現(xiàn)在為止可以證明此次OOM異常不是因?yàn)榫€(xiàn)程吃光所有的內(nèi)存而導(dǎo)致的。

線(xiàn)程數(shù)對(duì)比

上面提到，有兩個(gè)具體原因造成這個(gè)異常，我們上面已經(jīng)排除了第1個(gè)原因，那我們現(xiàn)在從第2個(gè)原因入手，評(píng)估是否操作系統(tǒng)設(shè)置了應(yīng)用創(chuàng)建線(xiàn)程的最大數(shù)量，并且已經(jīng)達(dá)到了最大允許數(shù)量。

在問(wèn)題出現(xiàn)的生產(chǎn)機(jī)器上使用ulimit -a來(lái)顯示當(dāng)前的各種系統(tǒng)對(duì)用戶(hù)使用資源的限制：

robert@robert-ubuntu1410：~$ ulimit -a 
core file size          (blocks, -c) 0 
data seg size           (kbytes, -d) unlimited 
scheduling priority             (-e) 0 
file size               (blocks, -f) unlimited 
pending signals                 (-i) 62819 
max locked memory       (kbytes, -l) 64 
max memory size         (kbytes, -m) unlimited 
open files                      (-n) 65535 
pipe size            (512 bytes, -p) 8 
POSIX message queues     (bytes, -q) 819200 
real-time priority              (-r) 0 
stack size              (kbytes, -s) 10240 
cpu time               (seconds, -t) unlimited 
max user processes              (-u) 1024 
virtual memory          (kbytes, -v) unlimited 
file locks                      (-x) unlimited

這里面我們看到生產(chǎn)機(jī)器設(shè)置的允許使用的最大用戶(hù)進(jìn)程數(shù)為1024：

max user processes (-u) 1024

現(xiàn)在，我們必須獲得問(wèn)題出現(xiàn)的時(shí)候，用戶(hù)下創(chuàng)建的線(xiàn)程情況。

在問(wèn)題產(chǎn)生的時(shí)候，我們使用前面小結(jié)介紹的JVM監(jiān)控命令jstack命令打印出了Java線(xiàn)程情況,jstack命令的示例輸出如下：

robert@robert-ubuntu1410:~$ jstack 2743 
2017-04-09 12:06:51 
Full thread dump Java HotSpot(TM) Server VM (25.20-b23 mixed mode): 
 
"Attach Listener" #23 daemon prio=9 os_prio=0 tid=0xc09adc00 nid=0xb4c waiting on condition [0x00000000] 
   java.lang.Thread.State: RUNNABLE 
 
"http-nio-8080-Acceptor-0" #22 daemon prio=5 os_prio=0 tid=0xc3341000 nid=0xb02 runnable [0xbf1bd000] 
   java.lang.Thread.State: RUNNABLE 
    at sun.nio.ch.ServerSocketChannelImpl.accept0(Native Method) 
    at sun.nio.ch.ServerSocketChannelImpl.accept(ServerSocketChannelImpl.java:241) 
    - locked <0xcf8938d8> (a java.lang.Object) 
    at org.apache.tomcat.util.net.NioEndpoint$Acceptor.run(NioEndpoint.java:688) 
    at java.lang.Thread.run(Thread.java:745) 
 
"http-nio-8080-ClientPoller-1" #21 daemon prio=5 os_prio=0 tid=0xc35bc400 nid=0xb01 runnable [0xbf1fe000] 
   java.lang.Thread.State: RUNNABLE 
    at sun.nio.ch.EPollArrayWrapper.epollWait(Native Method) 
    at sun.nio.ch.EPollArrayWrapper.poll(EPollArrayWrapper.java:269) 
    at sun.nio.ch.EPollSelectorImpl.doSelect(EPollSelectorImpl.java:79) 
    at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86) 
    - locked <0xcf99b100> (a sun.nio.ch.Util$2) 
    - locked <0xcf99b0f0> (a java.util.Collections$UnmodifiableSet) 
    - locked <0xcf99aff8> (a sun.nio.ch.EPollSelectorImpl) 
    at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:97) 
    at org.apache.tomcat.util.net.NioEndpoint$Poller.run(NioEndpoint.java:1052) 
    at java.lang.Thread.run(Thread.java:745) 
......

從jstack命令的輸出并統(tǒng)計(jì)后，我們得知，JVM一共創(chuàng)建了904個(gè)線(xiàn)程，但是，這還沒(méi)有到最大的進(jìn)程限制1024。

robert@robert-ubuntu1410:~$ grep "Thread " js.log | wc -l 
     904

這是我們思考，除了JVM創(chuàng)建的應(yīng)用層線(xiàn)程，JVM本身可能會(huì)有一些管理線(xiàn)程存在，而且操作系統(tǒng)內(nèi)用戶(hù)下可能也會(huì)有守護(hù)線(xiàn)程在運(yùn)行。

我們繼續(xù)從操作系統(tǒng)的角度來(lái)統(tǒng)計(jì)線(xiàn)程數(shù)，我們使用上面小結(jié)介紹的Linux操作系統(tǒng)命令pstack，并得到如下的輸出：

PID   LWP USER     %CPU %MEM CMD 
    1     1 root      0.0  0.0 /sbin/init 
    2     2 root      0.0  0.0 [kthreadd] 
    3     3 root      0.0  0.0 [migration/0] 
    4     4 root      0.0  0.0 [ksoftirqd/0] 
    5     5 root      0.0  0.0 [migration/0] 
    6     6 root      0.0  0.0 [watchdog/0] 
    7     7 root      0.0  0.0 [migration/1] 
    8     8 root      0.0  0.0 [migration/1] 
    9     9 root      0.0  0.0 [ksoftirqd/1] 
   10    10 root      0.0  0.0 [watchdog/1] 
   11    11 root      0.0  0.0 [migration/2] 
   12    12 root      0.0  0.0 [migration/2] 
   13    13 root      0.0  0.0 [ksoftirqd/2] 
   14    14 root      0.0  0.0 [watchdog/2] 
   15    15 root      0.0  0.0 [migration/3] 
   16    16 root      0.0  0.0 [migration/3] 
   17    17 root      0.0  0.0 [ksoftirqd/3] 
   18    18 root      0.0  0.0 [watchdog/3] 
   19    19 root      0.0  0.0 [events/0] 
   20    20 root      0.0  0.0 [events/1] 
   21    21 root      0.0  0.0 [events/2] 
   22    22 root      0.0  0.0 [events/3] 
   23    23 root      0.0  0.0 [cgroup] 
   24    24 root      0.0  0.0 [khelper] 
 
 ...... 
 
 7257  7257 zabbix    0.0  0.0 /usr/local/zabbix/sbin/zabbix_agentd: active checks #2 [idle 1 sec] 
 7258  7258 zabbix    0.0  0.0 /usr/local/zabbix/sbin/zabbix_agentd: active checks #3 [idle 1 sec] 
 7259  7259 zabbix    0.0  0.0 /usr/local/zabbix/sbin/zabbix_agentd: active checks #4 [idle 1 sec] 
 
 ...... 
 
 9040  9040 app       0.0 30.5 /apps/prod/jdk1.6.0_24/bin/java -Dnop -Djava.util.logging.manager=org.apache.juli.ClassLoaderLogManager -Ddbconfigpath=/apps/dbconfig/ -Djava.io.tmpdir=/apps/data/java-tmpdir -server -Xms2048m -Xmx2048m -XX:PermSize=128m -XX:MaxPermSize=512m -Dcom.sun.management.jmxremote -Djava.rmi.server.hostname=192.168.10.194 -Dcom.sun.management.jmxremote.port=6969 -Dcom.sun.management.jmxremote.ssl=false -Dcom.sun.management.jmxremote.authenticate=false -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/tmp -Xshare:off -Dhostname=sjsa-trade04 -Djute.maxbuffer=41943040 -Djava.net.preferIPv4Stack=true -Dfile.encoding=UTF-8 -Dworkdir=/apps/data/tomcat-work -Djava.endorsed.dirs=/apps/product/tomcat-trade/endorsed -classpath commonlib:/apps/product/tomcat-trade/bin/bootstrap.jar:/apps/product/tomcat-trade/bin/tomcat-juli.jar -Dcatalina.base=/apps/product/tomcat-trade -Dcatalina.home=/apps/product/tomcat-trade -Djava.io.tmpdir=/apps/data/tomcat-temp/ org.apache.catalina.startup.Bootstrap start 
 9040  9041 app       0.0 30.5 /apps/prod/jdk1.6.0_24/bin/java -Dnop -Djava.util.logging.manager=org.apache.juli.ClassLoaderLogManager -Ddbconfigpath=/apps/dbconfig/ -Djava.io.tmpdir=/apps/data/java-tmpdir -server -Xms2048m -Xmx2048m -XX:PermSize=128m -XX:MaxPermSize=512m -Dcom.sun.management.jmxremote -Djava.rmi.server.hostname=192.168.10.194 -Dcom.sun.management.jmxremote.port=6969 -Dcom.sun.management.jmxremote.ssl=false -Dcom.sun.management.jmxremote.authenticate=false -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/tmp -Xshare:off -Dhostname=sjsa-trade04 -Djute.maxbuffer=41943040 -Djava.net.preferIPv4Stack=true -Dfile.encoding=UTF-8 -Dworkdir=/apps/data/tomcat-work -Djava.endorsed.dirs=/apps/product/tomcat-trade/endorsed -classpath commonlib:/apps/product/tomcat-trade/bin/bootstrap.jar:/apps/product/tomcat-trade/bin/tomcat-juli.jar -Dcatalina.base=/apps/product/tomcat-trade -Dcatalina.home=/apps/product/tomcat-trade -Djava.io.tmpdir=/apps/data/tomcat-temp/ org.apache.catalina.startup.Bootstrap start 
 
......

通過(guò)命令統(tǒng)計(jì)用戶(hù)下已經(jīng)創(chuàng)建的線(xiàn)程數(shù)為1021。

$ grep app pthreads.log | wc -l 
    1021

現(xiàn)在我們確定，1021的數(shù)字已經(jīng)相當(dāng)?shù)慕咏?021的最大進(jìn)程數(shù)了，正如前面我們提到，在Linux操作系統(tǒng)里，線(xiàn)程是通過(guò)輕量級(jí)的進(jìn)程實(shí)現(xiàn)的，因此，限制用戶(hù)的最大進(jìn)程數(shù)，就是限制用戶(hù)的最大線(xiàn)程數(shù)，至于為什么沒(méi)有精確達(dá)到1024這個(gè)最大值就已經(jīng)報(bào)出異常，應(yīng)該是系統(tǒng)的自我保護(hù)功能，在還剩下3個(gè)線(xiàn)程的前提下，就開(kāi)始報(bào)錯(cuò)。

到此為止，我們已經(jīng)通過(guò)分析來(lái)找到問(wèn)題的原因，但是，我們還是不知道為什么會(huì)創(chuàng)建這么多的線(xiàn)程，從第一個(gè)輸出得知，JVM已經(jīng)創(chuàng)建的應(yīng)用線(xiàn)程有907個(gè)，那么他們都在做什么事情呢?

于是，在問(wèn)題發(fā)生的時(shí)候，我們又使用JVM的jstack命令，查看輸出得知，每個(gè)線(xiàn)程都阻塞在打印日志的語(yǔ)句上，log4j中打印日志的代碼實(shí)現(xiàn)如下：

public void callAppenders(LoggingEvent event) { 
    int writes = 0; 
    for(Category c = this; c != null; c=c.parent) { 
        // Protected against simultaneous call to addAppender, removeAppender,... 
        synchronized(c) { 
            if(c.aai != null) { 
                writes += c.aai.appendLoopOnAppenders(event); 
            } 
            if(!c.additive) { 
                break; 
            } 
        } 
    } 
    if(writes == 0) { 
        repository.emitNoAppenderWarning(this); 
    } 
}

在log4j中，打印日志有一個(gè)鎖，鎖的作用是讓打印日志可以串行，保證日志在日志文件中的正確性和順序性。

那么，新的問(wèn)題又來(lái)了，為什么只有凌晨0點(diǎn)會(huì)出現(xiàn)打印日志阻塞，其他時(shí)間會(huì)偶爾發(fā)生呢?這時(shí)，我們帶著新的線(xiàn)索又回到問(wèn)題開(kāi)始的思路，凌晨12點(diǎn)應(yīng)用沒(méi)有定時(shí)任務(wù)，系統(tǒng)會(huì)不會(huì)有其他的IO密集型的任務(wù)，比如說(shuō)歸檔日志、磁盤(pán)備份等?

經(jīng)過(guò)與運(yùn)維部門(mén)碰頭，基本確定是每天凌晨0點(diǎn)日志切割導(dǎo)致磁盤(pán)IO被占用，于是堵塞打印日志，日志是每個(gè)工作任務(wù)都必須的，日志阻塞，線(xiàn)程池就阻塞，線(xiàn)程池阻塞就導(dǎo)致線(xiàn)程池被撐大，線(xiàn)程池里面的線(xiàn)程數(shù)超過(guò)1024就會(huì)報(bào)錯(cuò)。

到這里，我們基本確定了問(wèn)題的原因，但是還需要對(duì)日志切割導(dǎo)致IO增大進(jìn)行分析和論證。

首先我們使用前面小結(jié)介紹的vmstat查看問(wèn)題發(fā)生時(shí)IO等待數(shù)據(jù)：

vmstat 2 1 >> /tmp/vm.log 
procs -----------memory---------- ---swap-- -----io---- --system-- -----cpu----- 
 r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id wa st 
 3  0 177608 725636  31856 3899144    0    0     2    10    0    0  39  1 1  59  0     
Tue Jul 5 00:27:51 CST 2016

可見(jiàn)，問(wèn)題發(fā)生的時(shí)候，CPU的IO等待為59%，同時(shí)又與運(yùn)維部門(mén)同事復(fù)盤(pán)，運(yùn)維同事確認(rèn)，腳本切割通過(guò)cat命令方法，先把日志文件cat后，通過(guò)管道打印到另外一個(gè)文件，再清空原文件，因此，一定會(huì)導(dǎo)致IO的上升。

其實(shí)，問(wèn)題的過(guò)程中，還有一個(gè)疑惑，我們認(rèn)為線(xiàn)程被IO阻塞，線(xiàn)程池被撐開(kāi)，導(dǎo)致線(xiàn)程增多，于是，我們查看了一下Tomcat線(xiàn)程池的設(shè)置，我們發(fā)現(xiàn)Tomcat線(xiàn)程池設(shè)置了800，按理說(shuō)，永遠(yuǎn)不會(huì)超過(guò)1024。

<Connector port="8080"      
               maxThreads="800" minSpareThreads="25" maxSpareThreads="75"      
               enableLookups="false" redirectPort="8443" acceptCount="100"      
               debug="0" connectionTimeout="20000"       
               disableUploadTimeout="true" />

關(guān)鍵在于，筆者所在的支付平臺(tái)服務(wù)化架構(gòu)中，使用了兩套服務(wù)化框架，一個(gè)是基于dubbo的框架，一個(gè)是點(diǎn)對(duì)點(diǎn)的RPC，用來(lái)緊急情況下dubbo服務(wù)出現(xiàn)問(wèn)題，服務(wù)降級(jí)使用。

每個(gè)服務(wù)都配置了點(diǎn)對(duì)點(diǎn)的RPC服務(wù)，并且獨(dú)享一個(gè)線(xiàn)程池：

<Connector port="8090"      
               maxThreads="800" minSpareThreads="25" maxSpareThreads="75"      
               enableLookups="false" redirectPort="8443" acceptCount="100"      
               debug="0" connectionTimeout="20000"       
               disableUploadTimeout="true" />

由于我們?cè)趯?duì)dubbo服務(wù)框架進(jìn)行定制化的時(shí)候，設(shè)計(jì)了自動(dòng)降級(jí)原則，如果dubbo服務(wù)負(fù)載變高，會(huì)自動(dòng)切換到點(diǎn)對(duì)點(diǎn)的RPC框架，這也符合微服務(wù)的失效轉(zhuǎn)移原則，但是設(shè)計(jì)中沒(méi)有進(jìn)行全面的考慮，一旦一部分服務(wù)切換到了點(diǎn)對(duì)點(diǎn)的RPC，而一部分的服務(wù)沒(méi)有切換，就導(dǎo)致兩個(gè)現(xiàn)場(chǎng)池都被撐滿(mǎn)，于是超過(guò)了1024的限制，就出了問(wèn)題。

到這里，我們基本可以驗(yàn)證，問(wèn)題的根源是日志切割導(dǎo)致IO負(fù)載增加，然后阻塞線(xiàn)程池，最后發(fā)生OOM：unable to create new native thread。

剩下的任務(wù)就是最小化重現(xiàn)的問(wèn)題，通過(guò)實(shí)踐來(lái)驗(yàn)證問(wèn)題的原因。我們與性能壓測(cè)部門(mén)溝通，提出壓測(cè)需求：

Tomcat線(xiàn)程池最大設(shè)置為1500.
操作系統(tǒng)允許的最大用戶(hù)進(jìn)程數(shù)1024.
在給服務(wù)加壓的過(guò)程中，需要人工制造繁忙的IO操作，IO等待不得低于50%。

經(jīng)過(guò)壓測(cè)壓測(cè)部門(mén)的一下午努力，環(huán)境搞定，結(jié)果證明完全可以重現(xiàn)此問(wèn)題。

最后，與所有相關(guān)部門(mén)討論和復(fù)盤(pán)，應(yīng)用解決方案，解決方案包括：

全部應(yīng)用改成按照小時(shí)切割，或者直接使用log4j的日志滾動(dòng)功能。
Tomcat線(xiàn)程池的線(xiàn)程數(shù)設(shè)置與操作系統(tǒng)的線(xiàn)程數(shù)設(shè)置不合理，適當(dāng)?shù)臏p少Tomcat線(xiàn)程池線(xiàn)程數(shù)量的大小。
升級(jí)log4j日志，使用logback或者log4j2。

這次OOM問(wèn)題的可以歸結(jié)為“多個(gè)因、多個(gè)果、多臺(tái)機(jī)器、多個(gè)服務(wù)池、不同時(shí)間”，針對(duì)這個(gè)問(wèn)題，與運(yùn)維部、監(jiān)控部和性能壓測(cè)部門(mén)的同事奮斗了幾天幾夜，終于通過(guò)在線(xiàn)上抓取信息、分析問(wèn)題、在性能壓測(cè)部門(mén)同事的幫助下，最小化重現(xiàn)問(wèn)題并找到問(wèn)題的根源原因，最后，針對(duì)問(wèn)題產(chǎn)生的根源提供了有效的方案。

3. 與監(jiān)控同事現(xiàn)場(chǎng)編寫(xiě)的腳本

本節(jié)提供一個(gè)筆者在實(shí)踐過(guò)程中解決OOM問(wèn)題的一個(gè)簡(jiǎn)單腳本，這個(gè)腳本是為了解決OOM(unable to create native thread)的問(wèn)題而在問(wèn)題機(jī)器上臨時(shí)編寫(xiě)，并臨時(shí)使用的，腳本并沒(méi)有寫(xiě)的很專(zhuān)業(yè)，筆者也沒(méi)有進(jìn)行優(yōu)化，保持原汁原味的風(fēng)格，這樣能讓讀者有種身臨其境的感覺(jué)，只是為了抓取需要的信息并解決問(wèn)題，但是在線(xiàn)上問(wèn)題十分火急的情況下，這個(gè)腳本會(huì)有大用處。

#!/bin/bash 
 
ps -Leo pid,lwp,user,pcpu,pmem,cmd >> /tmp/pthreads.log 
echo "ps -Leo pid,lwp,user,pcpu,pmem,cmd >> /tmp/pthreads.log" >> /tmp/pthreads.log 
echo `date` >> /tmp/pthreads.log 
echo 1 
 
pid=`ps aux|grep tomcat|grep cwh|awk -F ' ' '{print $2}'` 
echo 2 
 
echo "pstack $pid >> /tmp/pstack.log" >> /tmp/pstack.log 
pstack $pid >> /tmp/pstack.log 
echo `date` >> /tmp/pstack.log 
echo 3 
 
echo "lsof >> /tmp/sys-o-files.log" >> /tmp/sys-o-files.log 
lsof >> /tmp/sys-o-files.log 
echo `date` >> /tmp/sys-o-files.log 
echo 4 
 
echo "lsof -p $pid >> /tmp/service-o-files.log" >> /tmp/service-o-files.log 
lsof -p $pid >> /tmp/service-o-files.log 
echo `date` >> /tmp/service-o-files.log 
echo 5 
 
echo "jstack -l $pid  >> /tmp/js.log" >> /tmp/js.log 
jstack -l -F $pid  >> /tmp/js.log 
echo `date` >> /tmp/js.log 
echo 6  
 
echo "free -m >> /tmp/free.log" >> /tmp/free.log 
free -m >> /tmp/free.log 
echo `date` >> /tmp/free.log 
echo 7 
 
echo "vmstat 2 1 >> /tmp/vm.log" >> /tmp/vm.log 
vmstat 2 1 >> /tmp/vm.log 
echo `date` >> /tmp/vm.log 
echo 8 
 
echo "jmap -dump:format=b,file=/tmp/heap.hprof 2743" >> /tmp/jmap.log 
jmap -dump:format=b,file=/tmp/heap.hprof >> /tmp/jmap.log 
echo `date` >> /tmp/jmap.log 
echo 9 
 
echo end