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

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

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

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

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

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

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

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

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

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

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

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

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

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

  • 揭開(kāi)真相的面紗

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

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

CPU 何故飆升？

  • 起飛的 CPU，永不止步

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

image

  • 找到幕后的線程

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

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

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

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

image

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

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

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

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

  • JVM堆棧信息

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

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

[admin@my-linux~]$ jstack 48172

JVM堆棧信息是線程運(yùn)行時(shí)的執(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>

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

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

  • 線程與JVM堆棧信息

    通過(guò)top -Hp命令我們找到top線程ID排行,那如何通過(guò)線程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)記。同時(shí)在其他幾個(gè)top線程工作內(nèi)容也是垃圾回收相關(guān)，如下圖：

image

由此可見(jiàn)，CPU飆升的根本原因是因?yàn)槔厥掌骶€程一直在工作導(dǎo)致，我們的排查目標(biāo)從CPU轉(zhuǎn)移到了內(nèi)存。

繁忙的垃圾回收器

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

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

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

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

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

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

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

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

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

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

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

image

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


image
image

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

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

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

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

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

總結(jié)

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

好了，今天就聊到這里，我是可愛(ài)豬豬，下篇文章再會(huì)！

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

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

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

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

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