JVM困局的攻與破：京東小哥手把手教給你5種常見的JVM殺手锏

hello 寶兒們 周末好
我是京東碼農(nóng)小哥 ──可愛豬豬
不知道 618 剁手或者護(hù)航的你是否有新的收獲？
那么今天和大家聊聊一個話題 ──JVM 困局的攻與破
JVM 實踐對于很多新手來說有點撓破頭皮、無從下手的感覺
總覺得是一座邁不過去的大山
不過，不要緊，以后遇到 JVM 實踐上的問題與困擾
不妨先收藏這篇文章或許能夠幫助到工作中漫無頭緒的你

JVM 實踐有特定的方法論，讀完這篇文章你將有以下收獲：

  • http 接口超時的常見排查思路及方法
  • JVM 內(nèi)存&垃圾回收常用實踐命令
  • 系統(tǒng) CPU 飆高與資源消耗的線程定位
  • 如何分析 JVM 線程堆棧日志和內(nèi)存 Dump
  • Excel 文件導(dǎo)出與下載的正確姿勢
  • 客戶端與MQ連接超時的是是非非

以下文章閱讀預(yù)計需要 15 分鐘，目錄:

  • 是什么導(dǎo)致接口超時? * 發(fā)現(xiàn)問題，初步診斷
    • 根據(jù)初診，進(jìn)而確認(rèn)
    • 揭開真相的面紗
  • CPU何故飆升? * 起飛的 CPU，永不止步
    • 找到幕后的線程
    • JVM堆棧信息
    • 線程與JVM堆棧信息
    • 剖析JVM堆棧信息
  • 繁忙的垃圾回收器? * 監(jiān)控垃圾回收
    • Who侵蝕了JVM的內(nèi)存？
    • JVM堆棧信息
  • Excel導(dǎo)出工具選擇？
  • 并發(fā)癥：鏈接MQ異常，為何？
  • 總結(jié)

是什么導(dǎo)致接口超時？

其實每個程序員都是名偵探柯南 ,通過蛛絲馬跡牽出大案件，今天要和大家分享一個接口超時與JVM之間的故事

  • 發(fā)現(xiàn)問題，初步診斷

測試反應(yīng)線上出現(xiàn)接口超時，根據(jù)經(jīng)驗，這種情況 80%由 SQL 語句慢、鎖等待、代碼阻塞、長任務(wù)執(zhí)行等引起的接口執(zhí)行時間超出了 http 請求的超時時間所致。

以下是瀏覽器定時發(fā)起該接口的 http 請求，短則毫秒級響應(yīng)、長則 3、5 秒乃至超時。

image
  • 根據(jù)初診，進(jìn)而確認(rèn)

遇到這種情況，例行檢查代碼，找到性能低的 SQL 語句或者代碼進(jìn)行調(diào)優(yōu)基本可以解決同類問題。

于是，便查看超時接口getTaskStatus的實現(xiàn)邏輯：

public DownloadTaskInfo getTaskStatus(String taskId) {
        DownloadTaskInfo taskInfo;
        // 1.獲取redis中任務(wù)的狀態(tài)
        String taskInfoStr = redisUtil.get(taskId);
        if (taskInfoStr == null) {
            taskInfo = new DownloadTaskInfo();
            taskInfo.setTaskId(taskId);
            taskInfo.setStatus(DownloadTaskStatusEnum.NOT_START.getCode());
            return taskInfo;
        }
        return JSONUtil.toBean(taskInfoStr, DownloadTaskInfo.class);
    }

該接口是前端每 4 秒請求導(dǎo)出任務(wù)的執(zhí)行狀態(tài)，然而并沒有發(fā)現(xiàn) SQL 語句，所以排除掉 SQL 性能所致， 唯一可疑點:redisUtil.get(taskId)訪問 redis 超時？難不成前端 4 秒請求一次 redis 把 redis 服務(wù)器性能拉低了？ 或者 redis 服務(wù)被其他應(yīng)用（該 redis 多應(yīng)用公用）使用導(dǎo)致服務(wù)器性能下降？ 排查各個 redis 服務(wù)器各項指標(biāo)、日志都是正常的，排查掉唯一可能由代碼或者數(shù)據(jù)庫導(dǎo)致接口超時的原因

  • 揭開真相的面紗

    寶兒們，是不是跟我一樣排查到此，突然有種思路 Offline 的感覺？
    不知道你在使用 Windows 系統(tǒng)的時候是不是有遇到過電腦 CPU 超過 90%,連打開一個文件夾都特別慢呢？

咦？難道是服務(wù)器 CPU 所致？我們都知道 CPU 通過分配時間片來工作，接口調(diào)用過來需要 CPU 來處理，如果 CPU 繁忙，那么新進(jìn)來的任務(wù)只有等待...

CPU 何故飆升？

  • 起飛的 CPU，永不止步

為了重現(xiàn)問題，點擊了系統(tǒng)的[導(dǎo)出]按鈕，瀏覽器再次發(fā)起了getTaskStatus 接口的定時調(diào)用，紅框內(nèi)為 CPU 的狀態(tài)：持續(xù)飆升~

image

  • 找到幕后的線程

CPU占用與線程的執(zhí)行是密切相關(guān)的，只有找到真正忙碌的線程，找到線程的最終目的是分析出有問題的代碼或者任務(wù)！
那么問題來了？通過什么樣的手段或者方法才能找到Top線程呢？其實很簡單，執(zhí)行以下命令：

#1.查找Java進(jìn)程Id
[admin@my-linux~]$ jps
20704 Jps
48172 Application

#2.根據(jù)進(jìn)程ID，統(tǒng)計top線程
[admin@my-linux~]$ top -Hp 48172

linux top線程命令,執(zhí)行結(jié)果如圖：

image

該圖反應(yīng)了幾項重要的信息:

  • 列表中線程CPU占用排行由高到低排列。

  • 每一行信息中有內(nèi)存占比、CPU占比等關(guān)鍵信息。

  • 對我來說非常重要的一列：PID(線程ID)。通過PID我們可以找到對應(yīng)JVM線程堆棧信息。

  • JVM堆棧信息

    什么是JVM堆棧信息？有什么用？又如何查看呢？

    執(zhí)行jvm命令查看JVM堆棧信息：

[admin@my-linux~]$ jstack 48172

JVM堆棧信息是線程運行時的執(zhí)行狀態(tài)，以下為堆棧日志的快照：


<pre class="custom" style="margin-top: 10px; margin-bottom: 10px; border-radius: 5px; box-shadow: rgba(0, 0, 0, 0.55) 0px 2px 10px;">`"pool-10-thread-101" #1997 prio=5 os_prio=0 tid=0x00007fc88c0d5800 nid=0xc691 waiting on condition [0x00007fbb3608a000]
 java.lang.Thread.State: WAITING (parking)
  at sun.misc.Unsafe.park(Native Method)
  - parking to wait for  <0x0000000083e37320> (a java.util.concurrent.SynchronousQueue$TransferStack)
  at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
  at java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill(SynchronousQueue.java:458)
  at java.util.concurrent.SynchronousQueue$TransferStack.transfer(SynchronousQueue.java:362)
  at java.util.concurrent.SynchronousQueue.take(SynchronousQueue.java:924)
  at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1067)
  at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1127)
  at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
  at java.lang.Thread.run(Thread.java:745)` </pre>

  • 堆棧信息包含：線程名稱、狀態(tài)、執(zhí)行的代碼鏈路、線程的ID對應(yīng)十六進(jìn)制等

  • 它主要目的是定位線程出現(xiàn)長時間停頓的原因，如線程間死鎖、死循環(huán)、請求外部資源導(dǎo)致的長時間等待等。

  • 線程與JVM堆棧信息

    通過top -Hp命令我們找到top線程ID排行,那如何通過線程ID從JVM堆棧信息中定位到該信息呢？

    首先，將線程ID轉(zhuǎn)換為16進(jìn)制，比如上圖中，占用最高的線程Id:48391和51012，轉(zhuǎn)換后分別為bd07和c744：

image

其次，將轉(zhuǎn)換后的16進(jìn)制在JVM堆棧信息中進(jìn)行搜索。

  • 剖析JVM堆棧信息

線程Id:51012->c744,堆棧信息如下：

"pool-11-thread-1" #2039 prio=5 os_prio=0 tid=0x00007fbbfc057800 nid=0xc744 runnable [0x00007fbb35565000]
 java.lang.Thread.State: RUNNABLE
  at com.xxxx.utils.excel.Excel.setSheetBody(Excel.java:223)
  at com.xxxx.utils.excel.Excel.toXSSFWorkbook(Excel.java:130)
  at com.xxxx.utils.excel.Excel.writeOutput(Excel.java:82)
  at com.xxxx.utils.excel.Excel.getExcelBytes(Excel.java:99)

該代碼邏輯是執(zhí)行excel數(shù)據(jù)拼裝，屬于正常線程占用。

而，線程Id:48391->bd07,堆棧信息如下：

"Gang worker#8 (G1 Parallel Marking Threads)" os_prio=0 tid=0x00007fcf8c1dd800 nid=0xbd07 runnable

G1垃圾回收器線程正在進(jìn)行并行標(biāo)記。同時在其他幾個top線程工作內(nèi)容也是垃圾回收相關(guān)，如下圖：

image

由此可見，CPU飆升的根本原因是因為垃圾回收器線程一直在工作導(dǎo)致，我們的排查目標(biāo)從CPU轉(zhuǎn)移到了內(nèi)存。

繁忙的垃圾回收器

  • 監(jiān)控垃圾回收

既然JVM堆棧信息中有很多G1垃圾回收線程的工作日志，那是不是垃圾回收期真的如此繁忙的工作呢？我們使用JVM命令來監(jiān)控一下吧。

[admin@my-linux~]$ jstat -gcutil 48172 1000 100

以下截圖，一行即每一秒的內(nèi)存狀況：

image
  • E：代表新生代Eden區(qū)的空間占用比
  • YGC：代表新生代的垃圾回收次數(shù)

因此，我們可以快速判斷，Eden區(qū)非?？炀驼紳M，幾乎1~3秒就會觸發(fā)一次垃圾回收。實錘了，就是瘋狂的垃圾回收導(dǎo)致CPU持續(xù)飆升。

  • Who侵蝕了JVM的內(nèi)存？

為了弄清楚這個原因，我們不得不使用Java的另一條風(fēng)神令：jmap。

[admin@my-linux~]$ jmap -dump:format=b,file=m.dump 48172

通過jmap導(dǎo)出了JVM內(nèi)存的dump文件，用于JVM內(nèi)存分析。文件可能會比較大，所以最好準(zhǔn)備一個稍微大一點的目錄位置來存儲。

有了dump文件，我們怎么進(jìn)行分析呢？這時候需要借助另外一個客戶端工具：Memory Analyzer Tool,可以百度自行下載。
導(dǎo)入dump文件，工具會自動分析內(nèi)存的情況，下圖1.8GB是可疑內(nèi)存：

image

Leak suspects查看內(nèi)存占用詳情


image
image

大部分都是poi相關(guān)的類，也就是引入的excel工具，百度發(fā)現(xiàn)poi的XSSF的數(shù)據(jù)組裝全部在內(nèi)存，如果導(dǎo)出的數(shù)據(jù)比較多，內(nèi)存會一直持續(xù)上升。

Excel導(dǎo)出工具選擇？

由于使用poi的XSSF，所有數(shù)據(jù)在全部在內(nèi)存中進(jìn)行處理，如果數(shù)據(jù)量大，將會占用極高的內(nèi)存。
因此，推薦大家使用EasyExcel,EasyExcel是一個基于Java的簡單、省內(nèi)存的讀寫Excel的開源項目。在盡可能節(jié)約內(nèi)存的情況下支持讀寫百M的Excel

并發(fā)癥：鏈接MQ異常，為何？

基于以上的分析，發(fā)現(xiàn)內(nèi)存使用不釋放導(dǎo)致垃圾回收器線程繁忙工作，進(jìn)而CPU使用率比較高。間接導(dǎo)致接口超時等現(xiàn)象。
線程無法獲取到CPU時間片，同樣也會引發(fā)其他的并發(fā)癥：與MQ等中間件鏈接異常。 一些中間件和Client端通過心跳機(jī)制維持鏈接狀態(tài)。如果Server端在指定超時時間內(nèi)未收到心跳。會造成鏈接異常、超時等并發(fā)問題。

總結(jié)

今天，由一個接口超時，逐步排查到CPU、JVM內(nèi)存、Excel工具，逐步分析出問題的根因。
工欲善其事，必現(xiàn)利其器。jstat、jstack、jmap、top、MAT等命令和工具輔助我們分析問題起到了重要作用。
同時，內(nèi)存異常也可能導(dǎo)致一系列的并發(fā)癥。
今天文章比較長，如果你都看到了這里，給可愛豬豬點個贊或者在看。

好了，今天就聊到這里，我是可愛豬豬，下篇文章再會！

記得關(guān)注公眾號”面試怪圈“哦~好文章、好資料

?著作權(quán)歸作者所有,轉(zhuǎn)載或內(nèi)容合作請聯(lián)系作者
【社區(qū)內(nèi)容提示】社區(qū)部分內(nèi)容疑似由AI輔助生成，瀏覽時請結(jié)合常識與多方信息審慎甄別。
平臺聲明：文章內(nèi)容（如有圖片或視頻亦包括在內(nèi)）由作者上傳并發(fā)布，文章內(nèi)容僅代表作者本人觀點，簡書系信息發(fā)布平臺，僅提供信息存儲服務(wù)。

相關(guān)閱讀更多精彩內(nèi)容

  • 概述 性能優(yōu)化一向是后端服務(wù)優(yōu)化的重點，但是線上性能故障問題不是經(jīng)常出現(xiàn)，或者受限于業(yè)務(wù)產(chǎn)品，根本就沒辦法出現(xiàn)性能...
    前端三少爺閱讀 344評論 0贊 0
  • Java 應(yīng)用性能優(yōu)化是一個老生常談的話題，典型的性能問題如頁面響應(yīng)慢、接口超時，服務(wù)器負(fù)載高、并發(fā)數(shù)低，數(shù)據(jù)庫頻...
    Rick617閱讀 7,607評論 1贊 9
  • 表情是什么，我認(rèn)為表情就是表現(xiàn)出來的情緒。表情可以傳達(dá)很多信息。高興了當(dāng)然就笑了，難過就哭了。兩者是相互影響密不可...
    Persistenc_6aea閱讀 129,666評論 2贊 7
  • 16宿命：用概率思維提高你的勝算 以前的我是風(fēng)險厭惡者，不喜歡去冒險，但是人生放棄了冒險，也就放棄了無數(shù)的可能。 ...
    yichen大刀閱讀 7,856評論 0贊 4

友情鏈接更多精彩內(nèi)容