日韩无码专区无码一级三级片|91人人爱网站中日韩无码电影|厨房大战丰满熟妇|AV高清无码在线免费观看|另类AV日韩少妇熟女|中文日本大黄一级黄色片|色情在线视频免费|亚洲成人特黄a片|黄片wwwav色图欧美|欧亚乱色一区二区三区

RELATEED CONSULTING
相關(guān)咨詢
選擇下列產(chǎn)品馬上在線溝通
服務(wù)時(shí)間：8:30-17:00
你可能遇到了下面的問(wèn)題
關(guān)閉右側(cè)工具欄

新聞中心

這里有您想知道的互聯(lián)網(wǎng)營(yíng)銷解決方案
教你如何成為Java的OOMKiller

前言

雖然事隔半年，當(dāng)時(shí)排查線上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)題了，線上服務(wù)運(yùn)行非常健康，對(duì)可用性的保障起到了很大的作用，如果你在經(jīng)歷OOM，讀了這個(gè)文章會(huì)有很大的啟發(fā)。

Become OOM Killer

我們都知道JVM的內(nèi)存管理是自動(dòng)化的，Java語(yǔ)言的程序指針也不需要開發(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ò)誤的原因包括：

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

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

對(duì)于第2種異常，表示Java永久帶(方法區(qū))空間不夠，永久帶用于存放類的字節(jié)碼和長(zhǎng)常量池，類的字節(jié)碼加載后存放在這個(gè)區(qū)域，這和存放對(duì)象實(shí)例的堆區(qū)是不同的，大多數(shù)JVM的實(shí)現(xiàn)都不會(huì)對(duì)永久帶進(jìn)行垃圾回收，因此，只要類加載的過(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類，然后加載到方法區(qū)，因此，太多的JSP的Web工程可能產(chǎn)生這個(gè)異常。

對(duì)于第3種異常，本質(zhì)原因是創(chuàng)建了太多的線程，而能創(chuàng)建的線程數(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)系。

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

對(duì)于第1種異常，是JVM的線程由于遞歸或者方法調(diào)用層次太多，占滿了線程堆棧而導(dǎo)致的，線程堆棧默認(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)我們開始講述筆者經(jīng)歷的一次OOM問(wèn)題的定位和解決的過(guò)程。

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

在某一段時(shí)間內(nèi)，我們發(fā)現(xiàn)不同的業(yè)務(wù)服務(wù)開始偶發(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)題的異常如下：

 
 
 
 
    
  
  
  
  
  1. Caused by: java.lang.OutOfMemoryError: unable to create new native thread at java.lang.Thread.start0(Native Method) 
    2.   
  
  
  
  2. at java.lang.Thread.start(Thread.java:597) 
    3.   
  
  
  
  3. at java.util.Timer.(Timer.java:154) 
    4.

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ò)誤本身：

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

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

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

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

上面第1條資源指的是內(nèi)存，而第2條中，在Linux下線程使用輕量級(jí)進(jìn)程實(shí)現(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)建和銷毀、類的裝載等都發(fā)生在這里，本地內(nèi)存是Java應(yīng)用使用的一種特殊內(nèi)存，JVM并不直接管理其生命周期，每個(gè)線程也會(huì)有一個(gè)棧，是用來(lái)存儲(chǔ)線程工作過(guò)程中產(chǎn)生的方法局部變量、方法參數(shù)和返回值的，每個(gè)線程對(duì)應(yīng)的棧的默認(rèn)大小為1M。

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

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

因此，從內(nèi)存角度來(lái)看創(chuàng)建線程需要內(nèi)存空間，如果JVM進(jìn)程正當(dāng)一個(gè)應(yīng)用創(chuàng)建線程，而操作系統(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)建的最大線程數(shù)：

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

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

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

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

從上面輸出可以得出，生產(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)建線程數(shù)：

  • 700M / 1M = 700個(gè)線程

因此，根據(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)在為止可以證明此次OOM異常不是因?yàn)榫€程吃光所有的內(nèi)存而導(dǎo)致的。

線程數(shù)對(duì)比

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

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

 
 
 
 
    
  
  
  
  
  1. robert@robert-ubuntu1410：~$ ulimit -a 
    2.   
  
  
  
  2. core file size          (blocks, -c) 0 
    3.   
  
  
  
  3. data seg size           (kbytes, -d) unlimited 
    4.   
  
  
  
  4. scheduling priority             (-e) 0 
    5.   
  
  
  
  5. file size               (blocks, -f) unlimited 
    6.   
  
  
  
  6. pending signals                 (-i) 62819 
    7.   
  
  
  
  7. max locked memory       (kbytes, -l) 64 
    8.   
  
  
  
  8. max memory size         (kbytes, -m) unlimited 
    9.   
  
  
  
  9. open files                      (-n) 65535 
    10.   
  
  
  
  10. pipe size            (512 bytes, -p) 8 
    11.   
  
  
  
  11. POSIX message queues     (bytes, -q) 819200 
    12.   
  
  
  
  12. real-time priority              (-r) 0 
    13.   
  
  
  
  13. stack size              (kbytes, -s) 10240 
    14.   
  
  
  
  14. cpu time               (seconds, -t) unlimited 
    15.   
  
  
  
  15. max user processes              (-u) 1024 
    16.   
  
  
  
  16. virtual memory          (kbytes, -v) unlimited 
    17.   
  
  
  
  17. file locks                      (-x) unlimited 
    18.

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

 
 
 
 
    
  
  
  
  
  1. max user processes (-u) 1024 
    2.

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

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

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

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

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

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

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

 
 
 
 
    
  
  
  
  
  1. PID   LWP USER     %CPU %MEM CMD 
    2.   
  
  
  
  2.     1     1 root      0.0  0.0 /sbin/init 
    3.   
  
  
  
  3.     2     2 root      0.0  0.0 [kthreadd] 
    4.   
  
  
  
  4.     3     3 root      0.0  0.0 [migration/0] 
    5.   
  
  
  
  5.     4     4 root      0.0  0.0 [ksoftirqd/0] 
    6.   
  
  
  
  6.     5     5 root      0.0  0.0 [migration/0] 
    7.   
  
  
  
  7.     6     6 root      0.0  0.0 [watchdog/0] 
    8.   
  
  
  
  8.     7     7 root      0.0  0.0 [migration/1] 
    9.   
  
  
  
  9.     8     8 root      0.0  0.0 [migration/1] 
    10.   
  
  
  
  10.     9     9 root      0.0  0.0 [ksoftirqd/1] 
    11.   
  
  
  
  11.    10    10 root      0.0  0.0 [watchdog/1] 
    12.   
  
  
  
  12.    11    11 root      0.0  0.0 [migration/2] 
    13.   
  
  
  
  13.    12    12 root      0.0  0.0 [migration/2] 
    14.   
  
  
  
  14.    13    13 root      0.0  0.0 [ksoftirqd/2] 
    15.   
  
  
  
  15.    14    14 root      0.0  0.0 [watchdog/2] 
    16.   
  
  
  
  16.    15    15 root      0.0  0.0 [migration/3] 
    17.   
  
  
  
  17.    16    16 root      0.0  0.0 [migration/3] 
    18.   
  
  
  
  18.    17    17 root      0.0  0.0 [ksoftirqd/3] 
    19.   
  
  
  
  19.    18    18 root      0.0  0.0 [watchdog/3] 
    20.   
  
  
  
  20.    19    19 root      0.0  0.0 [events/0] 
    21.   
  
  
  
  21.    20    20 root      0.0  0.0 [events/1] 
    22.   
  
  
  
  22.    21    21 root      0.0  0.0 [events/2] 
    23.   
  
  
  
  23.    22    22 root      0.0  0.0 [events/3] 
    24.   
  
  
  
  24.    23    23 root      0.0  0.0 [cgroup] 
    25.   
  
  
  
  25.    24    24 root      0.0  0.0 [khelper] 
    26.   
  
  
  
  26.  
    27.   
  
  
  
  27.  ...... 
    28.   
  
  
  
  28.  
    29.   
  
  
  
  29.  7257  7257 zabbix    0.0  0.0 /usr/local/zabbix/sbin/zabbix_agentd: active checks #2 [idle 1 sec] 
    30.   
  
  
  
  30.  7258  7258 zabbix    0.0  0.0 /usr/local/zabbix/sbin/zabbix_agentd: active checks #3 [idle 1 sec] 
    31.   
  
  
  
  31.  7259  7259 zabbix    0.0  0.0 /usr/local/zabbix/sbin/zabbix_agentd: active checks #4 [idle 1 sec] 
    32.   
  
  
  
  32.  
    33.   
  
  
  
  33.  ...... 
    34.   
  
  
  
  34.  
    35.   
  
  
  
  35.  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 
    36.   
  
  
  
  36.  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 
    37.   
  
  
  
  37.  
    38.   
  
  
  
  38. ...... 
    39.

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

 
 
 
 
    
  
  
  
  
  1. $ grep app pthreads.log | wc -l 
    2.   
  
  
  
  2.     1021 
    3.

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

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

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

 
 
 
 
    
  
  
  
  
  1. public void callAppenders(LoggingEvent event) { 
    2.   
  
  
  
  2.     int writes = 0; 
    3.   
  
  
  
  3.     for(Category c = this; c != null; c=c.parent) { 
    4.   
  
  
  
  4.         // Protected against simultaneous call to addAppender, removeAppender,... 
    5.   
  
  
  
  5.         synchronized(c) { 
    6.   
  
  
  
  6.             if(c.aai != null) { 
    7.   
  
  
  
  7.                 writes += c.aai.appendLoopOnAppenders(event); 
    8.   
  
  
  
  8.             } 
    9.   
  
  
  
  9.             if(!c.additive) { 
    10.   
  
  
  
  10.                 break; 
    11.   
  
  
  
  11.             } 
    12.   
  
  
  
  12.         } 
    13.   
  
  
  
  13.     } 
    14.   
  
  
  
  14.     if(writes == 0) { 
    15.   
  
  
  
  15.         repository.emitNoAppenderWarning(this); 
    16.   
  
  
  
  16.     } 
    17.   
  
  
  
  17. } 
    18.

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

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

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

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

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

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

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

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

 
 
 
 
    
  
  
  
  
  1.   
  
  
  
  2.                maxThreads="800" minSpareThreads="25" maxSpareThreads="75"      
    3.   
  
  
  
  3.                enableLookups="false" redirectPort="8443" acceptCount="100"      
    4.   
  
  
  
  4.                debug="0" connectionTimeout="20000"       
    5.   
  
  
  
  5.                disableUploadTimeout="true" /> 
    6.

關(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è)線程池：

 
 
 
 
    
  
  
  
  
  1.   
  
  
  
  2.                maxThreads="800" minSpareThreads="25" maxSpareThreads="75"      
    3.   
  
  
  
  3.                enableLookups="false" redirectPort="8443" acceptCount="100"      
    4.   
  
  
  
  4.                debug="0" connectionTimeout="20000"       
    5.   
  
  
  
  5.                disableUploadTimeout="true" /> 
    6.

由于我們?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)池都被撐滿，于是超過(guò)了1024的限制，就出了問(wèn)題。

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

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

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

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

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

  1. 全部應(yīng)用改成按照小時(shí)切割，或者直接使用log4j的日志滾動(dòng)功能。
  2. Tomcat線程池的線程數(shù)設(shè)置與操作系統(tǒng)的線程數(shù)設(shè)置不合理，適當(dāng)?shù)臏p少Tomcat線程池線程數(shù)量的大小。
  3. 升級(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è)部門的同事奮斗了幾天幾夜，終于通過(guò)在線上抓取信息、分析問(wèn)題、在性能壓測(cè)部門同事的幫助下，最小化重現(xiàn)問(wèn)題并找到問(wèn)題的根源原因，最后，針對(duì)問(wèn)題產(chǎn)生的根源提供了有效的方案。

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

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

 
 
 
 
    
  
  
  
  
  1. #!/bin/bash 
    2.   
  
  
  
  2.  
    3.   
  
  
  
  3. ps -Leo pid,lwp,user,pcpu,pmem,cmd >> /tmp/pthreads.log 
    4.   
  
  
  
  4. echo "ps -Leo pid,lwp,user,pcpu,pmem,cmd >> /tmp/pthreads.log" >> /tmp/pthreads.log 
    5.   
  
  
  
  5. echo `date` >> /tmp/pthreads.log 
    6.   
  
  
  
  6. echo 1 
    7.   
  
  
  
  7.  
    8.   
  
  
  
  8. pid=`ps aux|grep tomcat|grep cwh|awk -F ' ' '{print $2}'` 
    9.   
  
  
  
  9. echo 2 
    10.   
  
  
  
  10.  
    11.   
  
  
  
  11. echo "pstack $pid >> /tmp/pstack.log" >> /tmp/pstack.log 
    12.   
  
  
  
  12. pstack $pid >> /tmp/pstack.log 
    13.   
  
  
  
  13. echo `date` >> /tmp/pstack.log 
    14.   
  
  
  
  14. echo 3 
    15.   
  
  
  
  15.  
    16.   
  
  
  
  16. echo "lsof >> /tmp/sys-o-files.log" >> /tmp/sys-o-files.log 
    17.   
  
  
  
  17. lsof >> /tmp/sys-o-files.log 
    18.   
  
  
  
  18. echo `date` >> /tmp/sys-o-files.log 
    19.   
  
  
  
  19. echo 4 
    20.   
  
  
  
  20.  
    21.   
  
  
  
  21. echo "lsof -p $pid >> /tmp/service-o-files.log" >> /tmp/service-o-files.log 
    22.   
  
  
  
  22. lsof -p $pid >> /tmp/service-o-files.log 
    23.   
  
  
  
  23. echo `date` >> /tmp/service-o-files.log 
    24.   
  
  
  
  24. echo 5 
    25.   
  
  
  
  25.  
    26.   
  
  
  
  26. echo "jstack -l $pid  >> /tmp/js.log" >> /tmp/js.log 
    27.   
  
  
  
  27. jstack -l -F $pid  >> /tmp/js.log 
    28.   
  
  
  
  28. echo `date` >> /tmp/js.log 
    29.   
  
  
  
  29. echo 6  
    30.   
  
  
  
  30.  
    31.   
  
  
  
  31. echo "free -m >> /tmp/free.log" >> /tmp/free.log 
    32.   
  
  
  
  32. free -m >> /tmp/free.log 
    33.   
  
  
  
  33. echo `date` >> /tmp/free.log 
    34.   
  
  
  
  34. echo 7 
    35.   
  
  
  
  35.  
    36.   
  
  
  
  36. echo "vmstat 2 1 >> /tmp/vm.log" >> /tmp/vm.log 
    37.   
  
  
  
  37. vmstat 2 1 >> /tmp/vm.log 
    38.   
  
  
  
  38. echo `date` >> /tmp/vm.log 
    39.   
  
  
  
  39. echo 8 
    40.   
  
  
  
  40.  
    41.   
  
  
  
  41. echo "jmap -dump:format=b,file=/tmp/heap.hprof 2743" >> /tmp/jmap.log 
    42.   
  
  
  
  42. jmap -dump:format=b,file=/tmp/heap.hprof >> /tmp/jmap.log 
    43.   
  
  
  
  43. echo `date` >> /tmp/jmap.log 
    44.   
  
  
  
  44. echo 9 
    45.   
  
  
  
  45.  
    46.   
  
  
  
  46. echo end 
    47.

如果讀者在線上已經(jīng)遇到了OOM的問(wèn)題，可以順著這個(gè)看似簡(jiǎn)陋而又信息滿滿的Java服務(wù)的監(jiān)控腳本的思路，利用本文提供的各種腳本和命令來(lái)深挖問(wèn)題的根本原因。

點(diǎn)擊《教你如何成為Java的OOM Killer》閱讀原文。

【本文為專欄作者“李艷鵬”的原創(chuàng)稿件，轉(zhuǎn)載可通過(guò)作者簡(jiǎn)書號(hào)(李艷鵬)或?qū)讷@取聯(lián)系】


文章題目：教你如何成為Java的OOMKiller
分享地址：http://www.5511xx.com/article/djhpepc.html