记一次 OOM 的原因和处理 出现大量 close_wait,项目无法访问 activeMq和 poi 出现的 OOM
生活随笔
收集整理的這篇文章主要介紹了
记一次 OOM 的原因和处理 出现大量 close_wait,项目无法访问 activeMq和 poi 出现的 OOM
小編覺得挺不錯的,現在分享給大家,幫大家做個參考.
大家好，我是烤鴨:
? ? ? 記一次項目無法訪問的事件和處理。由于某個模塊每隔幾天就會出現無法訪問，目前的最簡單粗暴的方法就是重啟。
1. 現象
? ? ? 項目內日志打印正常，經過dubbo的rpc服務和接口調用正常。http接口無法訪問。提示nginx 502。
?? ?
2. 原因猜想
? ? ? ?通常提示502 基本是項目本身原因。但是日志一直打印正常，很奇怪。
?? ?
3. 逐一排除
? ? 檢查了nginx，配置映射沒有問題。
?? ?以及從服務器本身通過curl localhost:端口的方式調用接口，發現也是調用不通。
?? ?猜想有沒有可能是連接被占滿，無法創建新的連接。
?? ?查看服務器該端口的連接。
?發現大量 close_wait，如圖所示。這就是項目訪問 502 的原因。
?? ?查看所有的tcp 連接命令。
? ?再就是查看日志發現大量的關于redis的warn日志。?io.lettuce.core.RedisConnectionException: Connection closed prematurely
[INFO] [lettuce-eventExecutorLoop-4-2] [2019-09-17 00:00:00,001] info(106) | Reconnecting, last destination was /127.0.1.44:6380 [INFO] [lettuce-eventExecutorLoop-4-3] [2019-09-17 00:00:00,001] info(106) | Reconnecting, last destination was /127.0.1.44:6380 [INFO] [lettuce-eventExecutorLoop-4-1] [2019-09-17 00:00:00,001] info(106) | Reconnecting, last destination was /127.0.1.45:6379 [INFO] [lettuce-nioEventLoop-6-2] [2019-09-17 00:00:00,004] info(106) | [channel=0xaaed8169, /127.0.1.47:21559 -> /127.0.1.44:6379, epid=0xd06cd] Closing channel because endpoint is already closed [INFO] [lettuce-nioEventLoop-6-3] [2019-09-17 00:00:00,004] info(106) | [channel=0x737b0658, /127.0.1.47:21560 -> /127.0.1.44:6379, epid=0xd06cf] Closing channel because endpoint is already closed [WARN] [lettuce-nioEventLoop-6-2] [2019-09-17 00:00:00,004] warn(146) | Cannot reconnect: io.lettuce.core.RedisConnectionException: Connection closed prematurely io.lettuce.core.RedisConnectionException: Connection closed prematurelyat io.lettuce.core.PlainChannelInitializer$1.channelInactive(PlainChannelInitializer.java:80)at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:245)at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:231)at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:224)at io.netty.channel.DefaultChannelPipeline$HeadContext.channelInactive(DefaultChannelPipeline.java:1429)at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:245)at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:231)at io.netty.channel.DefaultChannelPipeline.fireChannelInactive(DefaultChannelPipeline.java:947)at io.netty.channel.AbstractChannel$AbstractUnsafe$8.run(AbstractChannel.java:822)at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:163)at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:404)at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:463)at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:884)at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)at java.lang.Thread.run(Thread.java:748)猜測上面的連接過多無法釋放可能是跟redis有關。解決redis警告。
我們項目采用的redis的jar是下面這個。
里面有兩個數據源可以選擇，默認是lettuce，改為使用jedis。修改為如下。
<dependency><groupId>org.springframework.boot</groupId><artifactId>spring-boot-starter-data-redis</artifactId><version>2.0.5.RELEASE</version><exclusions><exclusion><groupId>io.lettuce</groupId><artifactId>lettuce-core</artifactId></exclusion></exclusions> </dependency>改完確實沒警告日志了，但是沒幾天，502問題又復現了。發現不是這個導致的 close_wait過多。
其實沒關系，這只是一個警告，理論上不會影響什么。可以看github上的issue。
https://github.com/lettuce-io/lettuce-core/issues/861
4. ?深度挖掘
當時并沒有往OOM考慮，畢竟項目的rpc接口調用正常。
生產環境由于沒權限是無法生成dump文件的，就在測試系統生成了一下，想看看日志中有沒有線程死鎖或者其他情況。
生成 dump 文件。
jmap -dump:file=/tmp/dump/heap.hprof [pid]使用 JProfiler 分析 dump日志。
jprofiler 下載地址：
?鏈接: https://pan.baidu.com/s/1WXaMUC7mJ3dH_WMc2kpDag 提取碼: dcec?
發現還是有點收獲的。搜索 Out 關鍵字，發現了驚喜。也就解釋了之前的現象。如圖。
找到問題了，但是還沒有找到問題的源頭。所以又出現問題后讓運維再次啟動的時候加大了 jvm內存，啟動命令添加 -Xms512m -Xmx2g 希望這次可以撐的多幾天。啟動后沒多久讓運維幫忙查看jvm內存情況，可以發現，沒幾個小時老年代的使用已經82%。
查看某進程的gc情況。
jmap -heap Pid Attaching to process ID 9782, please wait... Debugger attached successfully. Server compiler detected. JVM version is 25.191-b12using thread-local object allocation. Parallel GC with 4 thread(s)Heap Configuration:MinHeapFreeRatio = 0MaxHeapFreeRatio = 100MaxHeapSize = 2147483648 (2048.0MB)NewSize = 715653120 (682.5MB)MaxNewSize = 715653120 (682.5MB)OldSize = 1431830528 (1365.5MB)NewRatio = 2SurvivorRatio = 8MetaspaceSize = 21807104 (20.796875MB)CompressedClassSpaceSize = 1073741824 (1024.0MB)MaxMetaspaceSize = 17592186044415 MBG1HeapRegionSize = 0 (0.0MB)Heap Usage: PS Young Generation Eden Space:capacity = 603455488 (575.5MB)used = 178326152 (170.06507110595703MB)free = 425129336 (405.43492889404297MB)29.55083772475361% used From Space:capacity = 57671680 (55.0MB)used = 7215904 (6.881622314453125MB)free = 50455776 (48.118377685546875MB)12.512040571732955% used To Space:capacity = 54525952 (52.0MB)used = 0 (0.0MB)free = 54525952 (52.0MB)0.0% used PS Old Generationcapacity = 1431830528 (1365.5MB)used = 1177733640 (1123.1743240356445MB)free = 254096888 (242.32567596435547MB)82.25370370088939% used43209 interned Strings occupying 4908648 bytes.再去生產日志中搜索 'OutOfMemoryError' 附近的內容，定位原因。
兩處地方：
?? ?1.?? ?activeMq像隊列中推送的時候：ActiveMQSession.send
?? ?2.?? ?使用poi導出：org.apache.poi.POIXMLDocument.write
詳細日志如下：
5.?? ?分析代碼
既然找到問題了，就去分析下代碼吧。
5.1? ? ?poi導出的偽代碼如下:
List<CarSigned> carSignList = signingService.exportSignList(carSignedRequest);XSSFWorkbook workBook = new XSSFWorkbook();// 創建一個工作薄對象2007XSSFSheet xssfSheet = workBook.createSheet();String[] headers = {""};int rowIndex = 0;Row row = xssfSheet.createRow(rowIndex++);for (int i = 0; i < headers.length; i++) {row.createCell(i).setCellValue(headers[i]);}for (CarSigned carSignedListDto : carSignList) {row = xssfSheet.createRow(rowIndex++);// 車牌號row.createCell(1).setCellValue(carSignedListDto.getVehicleNo());}String date = new SimpleDateFormat("yyyy_MM_dd").format(new Date());String codefilename = "";String msie = "MSIE";String fileNames = "filename" + date + ".xlsx";String agent = request.getHeader("USER-AGENT");boolean flag = (null != agent && -1 != agent.indexOf(msie) || null != agent && -1 != agent.indexOf("Trident"));if (flag) {String name = java.net.URLEncoder.encode(fileNames, "UTF-8");// IEcodefilename = name;} else {// chrome,firefogcodefilename = fileNames;}response.setHeader("Content-Disposition","attachment;filename=" + new String(codefilename.getBytes("UTF-8"), "iso8859-1"));// 固定格式response.setContentType("application/ynd.ms-excel;charset=UTF-8");OutputStream out = response.getOutputStream();workBook.write(out);out.flush();out.close();說實話，和正常的導出沒什么區別，沒看出有什么問題，導出的量不到10w，理論上也不會OOME。
5.2? activemq工具類偽代碼
package com.xxx.util;import org.apache.activemq.ActiveMQConnectionFactory; import org.slf4j.Logger; import org.slf4j.LoggerFactory;import javax.jms.*; import java.util.HashMap; import java.util.Map; import java.util.Set;/*** mq 工具1* @author wu**/ public class MQProviderUtil {private static final Logger logger = LoggerFactory.getLogger(MQProviderUtil.class);public static void sendMq(Map<String, String> map,String user,String password,String brokerUrl,String topic) {// 連接Connection connection = null;// 會話 發送或者接收消息的線程Session session = null;// 消息的目的地Destination destination;// 消息生產者MessageProducer messageProducer;// 實例化連接工廠ConnectionFactory connectionFactory = new ActiveMQConnectionFactory(user,password,brokerUrl);try {// 通過連接工廠獲取連接connection = connectionFactory.createConnection();// 啟動連接connection.start();// 創建sessionsession = connection.createSession(true, Session.AUTO_ACKNOWLEDGE);// 創建一個叫sendFile的消息隊列destination = session.createQueue(topic);logger.info(" 創建一個叫"+topic+"的消息隊列");// 創建消息生產者messageProducer = session.createProducer(destination);MapMessage mapMsg = session.createMapMessage(); Set <String> set = map.keySet();for(String key:set){String value = map.get(key);mapMsg.setString(key,value);}/* mapMsg.setString("name", "李尋歡1");mapMsg.setBoolean("IsHero", true);mapMsg.setInt("age", 35);*///通過消息生產者發出消息messageProducer.send(mapMsg);session.commit();} catch (Exception e) {logger.info("activeMq消息隊列異常");e.printStackTrace();} finally {if (connection != null) {try {connection.close();session.close();} catch (Exception e2) {e2.printStackTrace();}}}}public static void main(String[] args) throws InterruptedException {for (int i = 0; i < 3000; i++) {Map<String,String> map = new HashMap<>();map.put("id","123");sendMq(map,"admin","admin","tcp://127.0.0.1:61616","signed");}} }單獨看這段代碼也沒有問題，運行main方法也能跑。
唯一有點問題的就是代碼里每次調用mq的地方都是調用 MQProviderUtil.sendMq 方法。
理論上實例化連接工廠只需要在項目初始化的時候創建一次，但是他每次調用都會創建。猜測可能是調用過于頻繁，導致工廠對象來不及回收導致的OOM。
activeMQ和springboot 組合使用的可以參考這篇文章:
https://segmentfault.com/a/1190000014108398
本地啟動項目，模擬線上并發量 *2，實測沒問題是來得及回收的，如圖JVM 回收曲線交替執行正常。
總結：
由于不是我們項目組，他們一直說是導出導致的，業務人員同時導出量過大，由于后臺生成的excel時候沒有采用分頁查詢，導致OOM。一次導出的數據大概在10W左右，除非惡意訪問，我覺得不是導出導致的OOM，或者說不是導出的產生的OOM，是導出的時候把這個OOM暴露出來了。
后來我又去activemq的機器查看了內存和cpu，一切正常。
activemq日志有時候會warn：但是問題不大
后來又查了mq的版本為 apache-activemq-5.13.1。2016年的版，官方寫的多線程有可能是導致OOM的。跟我們這廠家也不太符合。
http://activemq.apache.org/how-to-deal-with-large-number-of-threads-in-clients.html
后來換了個導出的工具類，就沒有OOM的問題了，好TM尷尬....真的是POI引起的OOM???
其實如果方便的話只要讓運維下次啟動的時候把OOM日志記錄到文件就好了。這樣分析起來就方便多了。現在沒問題了，也沒機會了。
-XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=./oom.out?
總結
以上是生活随笔為你收集整理的记一次 OOM 的原因和处理 出现大量 close_wait,项目无法访问 activeMq和 poi 出现的 OOM的全部內容，希望文章能夠幫你解決所遇到的問題。
- 上一篇： Servlet的运行方式
- 下一篇： 1、Canvas的基本用法