記錄一個(gè)別人的心得窝稿。原文連接如下：
https://my.oschina.net/u/3345762/blog/1784199?p=2
摘要: OOM low memory 宕機(jī) 內(nèi)存調(diào)優(yōu)
寫在前面：該篇宕機(jī)問題的排查難度遠(yuǎn)比上一篇（記一次解決線上OOM的心路歷程）大的太多煤搜，上一篇中內(nèi)存泄漏的問題是有跡可循的，本次的宕機(jī)在業(yè)務(wù)日志上沒有任何征兆列林，另外本文有許多值得深挖的點(diǎn)，希望讀者能找到自己感興趣的點(diǎn)進(jìn)行深挖，并將心得體會(huì)留言在評論區(qū)予权，讓大家共同進(jìn)步。
現(xiàn)象：zabbix告警生產(chǎn)環(huán)境應(yīng)用shutdown转绷，通過堡壘機(jī)登入生產(chǎn)環(huán)境伟件，查看應(yīng)用容器進(jìn)程，并發(fā)現(xiàn)沒有該業(yè)務(wù)應(yīng)用的相應(yīng)進(jìn)程议经，第一感覺進(jìn)程在某些條件下被系統(tǒng)殺死了斧账，然后查看容器日志谴返，發(fā)現(xiàn)均沒異常可尋咧织。
問題：
1嗓袱、為何會(huì)沒有應(yīng)用進(jìn)程及異常的日志輸出？如果真的是系統(tǒng)殺死了應(yīng)用進(jìn)程习绢，是什么條件觸發(fā)了它渠抹？
2、測試環(huán)境闪萄、UAT環(huán)境為何從未有這樣的情況梧却，差別在哪？
排查：
首先去查看生產(chǎn)環(huán)境系統(tǒng)資源情況及相應(yīng)容器的配置败去，查得該臺生產(chǎn)機(jī)器的總內(nèi)存是8G：
接著查看該應(yīng)用所在容器環(huán)境的變量設(shè)置：
#!/bin/sh
# chkconfig: 345 88 14
# description: Tomcat Daemon
set -m
#Change to your Jdk directory
SCRIPT_HOME=/home/appadmin/scripts/glink
export JAVA_HOME=/Data/software/jdk1.8.0_65
#Change to your Tomcat directory
CATALINA_HOME=/Data/software/tomcat-glink
export JAVA_OPTS="-server -Xms512m -Xmx4G
-XX:PermSize=128M
-XX:MaxNewSize=512m
-XX:MaxPermSize=256m
-Djava.awt.headless=true
-XX:+PrintGCDetails
-XX:+PrintGCApplicationStoppedTime
-XX:+PrintGCApplicationConcurrentTime
-XX:+PrintGCTimeStamps
-Xloggc:$CATALINA_HOME/logs/gc.log
-Djava.awt.headless=true
-Denv=prod
-Dproject=GLINK
-Dprofile=Production_us
-Dallow.push=true
-Dsave.directory=/Data/diamond/glink/config
-Dcat.app.name=GLINK_PROD
-Duser.timezone=GMT+08"
# Determine and execute action based on command line parameter
#-Ddiamond.conf.path=/Data/diamond/glink/diamond.properties
echo "Starting Best Glink Tomcat..."
DATE=`date "+%Y-%m-%d %H:%M:%S"`
echo "$DATE : user $USER starts tomcat." >> $SCRIPT_HOME/start.log
sh $CATALINA_HOME/bin/startup.sh
此處可以看到這里為java設(shè)置的最大內(nèi)存為4G放航，接著我們又查看了部署在本臺機(jī)器上的另一個(gè)應(yīng)用環(huán)境的設(shè)置，結(jié)果和該應(yīng)用一樣圆裕，設(shè)置的內(nèi)存大小為4G广鳍，我們繼續(xù)查看了該機(jī)器上的其他java應(yīng)用，發(fā)現(xiàn)另外還部署了一個(gè)本地queue（activitymq）吓妆，且設(shè)置的最大占用內(nèi)存為1G,此時(shí)似乎已經(jīng)可以猜測赊时，由于機(jī)器的總內(nèi)存不夠，當(dāng)應(yīng)用在申請新的內(nèi)存時(shí)行拢，由于環(huán)境變量設(shè)置的緣故并沒有去觸發(fā)GC祖秒，而是直接申請內(nèi)存，系統(tǒng)方發(fā)現(xiàn)總內(nèi)存已經(jīng)不夠用剂陡，于是直接將該應(yīng)用進(jìn)程殺死狈涮。
為了驗(yàn)證上面的說法，我們查找系統(tǒng)的相關(guān)日志：
less /var/log/messages
清晰地看到：Feb 23 00:01:09 us-app01 kernel: Out of memory: Kill process 14157 (java) score 619 or sacrifice child鸭栖，此處說明的確是系統(tǒng)殺死了應(yīng)用進(jìn)程歌馍，根據(jù)這里的系統(tǒng)日志查詢資料得知，系統(tǒng)會(huì)為每一塊新分配的內(nèi)存添加跟蹤記錄至low memory晕鹊，當(dāng)low memory的內(nèi)存耗盡同時(shí)有需要新分配內(nèi)存時(shí)松却，內(nèi)核便會(huì)觸發(fā)Kill process，此處為什么系統(tǒng)選擇了kill該應(yīng)用進(jìn)程溅话，我的猜想是一該應(yīng)用進(jìn)程屬于用戶進(jìn)程晓锻，它的結(jié)束并不會(huì)影響系統(tǒng)的正常運(yùn)行，二是由于該應(yīng)用最大可用內(nèi)存設(shè)置的不合理性飞几，需要新分配內(nèi)存來存儲(chǔ)對象就發(fā)生在其中砚哆。由于當(dāng)時(shí)的進(jìn)程已經(jīng)被系統(tǒng)殺死，我們無法得知當(dāng)時(shí)具體內(nèi)存的使用及分配情況屑墨，作為參考依據(jù)我們選擇查看相同環(huán)境下的另一臺機(jī)器的內(nèi)存情況：
此處可以看出系統(tǒng)的總內(nèi)存為7967m躁锁，low memory的總內(nèi)存也為7967,（64位的系統(tǒng)纷铣，系統(tǒng)總內(nèi)存與low memory相同），當(dāng)前l(fā)ow memory已經(jīng)使用7832（low memory = used + buff/cache）战转。
種種跡象表明：由于該應(yīng)用及部署在同一臺機(jī)器上的另一個(gè)應(yīng)用搜立，其環(huán)境中最大可用內(nèi)存設(shè)置的不合理（系統(tǒng)總內(nèi)存8G，這兩個(gè)應(yīng)用的最大可用內(nèi)存設(shè)置為4G槐秧，同時(shí)機(jī)器上還有一個(gè)本地queue）性啄踊，導(dǎo)致其內(nèi)部在申請內(nèi)存時(shí)由于系統(tǒng)的low memory被耗盡，觸使系統(tǒng)殺死了該應(yīng)用進(jìn)程刁标。
臨時(shí)解決：
減少應(yīng)用環(huán)境中的設(shè)置的最大可用內(nèi)存颠通，重啟應(yīng)用。
繼續(xù)解決：
應(yīng)用重啟后的一段時(shí)間（幾天后）命雀，我們查看應(yīng)用使用的內(nèi)存情況：
我們想到該應(yīng)用滿足的業(yè)務(wù)量很小并沒有那種數(shù)據(jù)量特別大的場景蒜哀，為何系統(tǒng)會(huì)使用掉這么多的內(nèi)存呢，于是我們決定對該應(yīng)用從代碼角度上進(jìn)行一些可行的調(diào)優(yōu)吏砂。
首先使用jmp dump出內(nèi)存快照，并導(dǎo)入jprofiler乘客，借助jprofiler進(jìn)行分析：
從上圖我們可以看到char[]占用了651m的內(nèi)存狐血，String占用的是10m左右，顯然這里對char類型的使用或者處理是有問題的易核，我們進(jìn)一步查看到底是什么地方使用了char[]匈织，又有哪些大的char[]實(shí)例，以及其中都存了怎樣的數(shù)據(jù)：
這里我們看到有將近20個(gè)char[]實(shí)例的大小都超過了10m牡直，其中最大的已然有30m缀匕，我們再查看這里都存了哪些數(shù)據(jù)：
此處可以看到其中有一些業(yè)務(wù)數(shù)據(jù)的記錄，另外其內(nèi)存數(shù)據(jù)中還有部分公司內(nèi)部任務(wù)中心的一些任務(wù)信息（此處就不截圖出來了）碰逸，于是我們隱隱感覺到是不是任務(wù)平臺做了什么事情乡小，比如收集日志什么的，我們繼續(xù)查看其引用情況：
看到此處的rabbit基本可以斷定了就是任務(wù)中心client的引用饵史，項(xiàng)目中其他地方并沒有用到rabbit满钟，于是我們找到任務(wù)中心的維護(hù)人員進(jìn)行詢問，他們的答案是不會(huì)去收集應(yīng)用的日志的（我們心里的答案也是這胳喷，又不是日志平臺的client湃番，任務(wù)中心團(tuán)隊(duì)不會(huì)做這么傻的事），然而我們在char[]中的確看到的都是任務(wù)平臺的信息這是怎么回事吭露？于是我們查看任務(wù)平臺客戶端的源碼及對外的api吠撮，看看能有什么線索，最終鎖定了一個(gè)問題讲竿，任務(wù)平臺客戶端使用了線程池泥兰，并且默認(rèn)的線程池中線程最多為100（這個(gè)是有些坑择浊，簡單說明，任務(wù)中心是通過queue實(shí)現(xiàn)的逾条，服務(wù)端發(fā)送任務(wù)消息琢岩，client收到后消費(fèi)）。
我們再看到截圖中的線程师脂，隱隱也是任務(wù)中心client的線程池中的線程担孔，于是我們進(jìn)一步查找到底哪里才會(huì)使用char[]，并且會(huì)有業(yè)務(wù)數(shù)據(jù)吃警，查看全局代碼后我們發(fā)現(xiàn)對于應(yīng)用中任務(wù)消息的處理器并沒有直接使用char[]糕篇，組內(nèi)一位同學(xué)提醒是不是使用log4j打日志處理不當(dāng)?shù)脑颍胍幌刖湍壳艾F(xiàn)狀而言酌心，這種說法說的通拌消，于是我們在每一個(gè)任務(wù)處理器中查看日志上有沒有大對象的輸出，果然找到了一些（訂單安券、庫存等....）墩崩。
private List<AmazonOrderInfo> getAmazonOrderNotInLocal(CustomerSalesChannelVO channel) {
List<AmazonOrderInfo> amazonOrderInfoList = new ArrayList<>();
try {
Date nowTime = new Date();
Date toTime = new Date(nowTime.getTime() - 121000);
Date fromTime = new Date(nowTime.getTime() - 720000);
amazonOrderInfoList = amazonOrderService.getAmazonOrderInfoNotInLocal(channel, fromTime, toTime);
BizLogger.info("get amazon new order when amazon inventory feedback, result ： " + amazonOrderInfoList);
} catch (Exception e) {
BizLogger.syserror("getAmazonOrderNotInLocal error,", e);
}
return amazonOrderInfoList;
}
//獲取本地amazon創(chuàng)建失敗的平臺訂單暫用的庫存量
private List<AmazonOrderItemVO> getAmazonErrorOrderInLocal(String customerCode) {
AmazonOrderSO so = new AmazonOrderSO();
so.setCustomerCode(customerCode);
so.setStatus(AmazonOrderStatus.ERROR);
List<AmazonOrderItemVO> amazonOrderItemVOList = amazonOrderService.getAmazonOrderItemVOList(so);
BizLogger.info("get amazon error order item in local when amazon inventory feedback, result : " + amazonOrderItemVOList);
return amazonOrderService.getAmazonOrderItemVOList(so);
}
if (CollectionUtils.isNotEmpty(inventoryAgeVOList)) {
BizLogger.info("send inventoryAge message." + inventoryAgeVOList);
sendInventoryAgeSyncMessage(asnVO.getCustomerCode(), inventoryAgeVOList);
}
于是我們查閱相關(guān)資料了解到log4j會(huì)將當(dāng)前線程中被打印的最長記錄的大小進(jìn)行緩存，至此該問題已經(jīng)說得通了侯勉。
由于任務(wù)中心的客戶端啟用了默認(rèn)最大線程數(shù)為100的線程池鹦筹，這些線程用來消費(fèi)服務(wù)端發(fā)送過來的任務(wù)消息，該業(yè)務(wù)應(yīng)用中配置很多關(guān)于庫存址貌、訂單的相應(yīng)任務(wù)铐拐，在這些具體任務(wù)消息的處理器中存在一定的大對象日志輸出。由于線程是用線程池維護(hù)练对，每次執(zhí)行完并不會(huì)被銷毀掉遍蟋，因此會(huì)存在大量的緩存區(qū)域。
這樣也就能回答我們最初設(shè)想的第二個(gè)問題：測試環(huán)境螟凭、UAT環(huán)境為何從未有這樣的情況虚青，差別在哪？差別有四個(gè)地方：
- 系統(tǒng)環(huán)境的內(nèi)存大小及虛機(jī)版本赂摆。
- 訂單數(shù)據(jù)或是庫存數(shù)據(jù)量的差異挟憔。
- 測試環(huán)境和UAT環(huán)境我們并不會(huì)配置很多的job，更多的是測試完就結(jié)束烟号。
- 應(yīng)用重啟的頻率不同绊谭，測試環(huán)境較為頻繁。
最終處理方案：
（1）將任務(wù)中心客戶端消費(fèi)任務(wù)消息的線程池的最大線程數(shù)按照應(yīng)用的實(shí)際情況改為10汪拥。
（2）去除對大對象的日志輸出达传。
同時(shí)將任務(wù)中心客戶端對于默認(rèn)線程池的最大線程數(shù)設(shè)置的不合理性進(jìn)行反饋，避免同樣的事情發(fā)生在其他項(xiàng)目組。
總結(jié)：
1宪赶、當(dāng)low memory被耗盡時(shí)宗弯，系統(tǒng)會(huì)kill掉不會(huì)影響自身穩(wěn)定運(yùn)行的用戶進(jìn)程。
2搂妻、應(yīng)用上線程池的最大線程數(shù)的設(shè)置需要根據(jù)機(jī)器環(huán)境及應(yīng)用本身進(jìn)行合理設(shè)置蒙保，尤其要注意依賴消息實(shí)現(xiàn)的三方工具包中的線程次設(shè)置，避免被其引用的對象使用過量的緩存等欲主。
3邓厕、在組內(nèi)會(huì)議中明確，任務(wù)處理器中不允許有大對象的日志輸出扁瓢。
