Arthas 官方社區(qū)正在舉行征文活動(dòng)，參加即有獎(jiǎng)品拿哦~點(diǎn)擊投稿

作者 | 張?jiān)葡?/p>

最近我們線上有個(gè)應(yīng)用服務(wù)器有點(diǎn)上頭，CPU總能跑到99%，我尋思著它流量也不大啊，為啥能把自己整這么累？于是我登上這臺(tái)服務(wù)器，看看它到底在干啥！

以前碰到類似問題，可能會(huì)考慮使用 top -Hp?加?jstack 命令去排查，雖然能大致定位到問題范圍，但有效信息還是太少了，多數(shù)時(shí)候還是要靠猜。今天向大家推薦一款更高效更精準(zhǔn)的工具：Arthas！Arthas 是 Alibaba 開源的 Java 診斷工具，能夠幫助我們快速定位線上問題。基本的安裝使用可以參考官方文檔：https://alibaba.github.io/arthas

這次我們利用它來排查 CPU 負(fù)載高的問題。CPU 負(fù)載過高一般是某個(gè)或某幾個(gè)線程有問題，所以我們嘗試使用第一個(gè)命令：thread，這個(gè)命令會(huì)顯示所有線程的信息，并且把 CPU 使用率高的線程排在前面。

[arthas@384]$ thread Threads Total: 112, NEW: 0, RUNNABLE: 26, BLOCKED: 0, WAITING: 31, TIMED_WAITING: 55, TERMINATED: 0 ID NAME STATE %CPU TIME 108 h..ec-0 RUNNABLE 51 4011:48 100 h..ec-2 RUNNABLE 48 4011:51 ...

為了方便閱讀，刪掉了一些不重要的信息

可以看到，CPU 資源幾乎被前兩個(gè)線程占滿，并且已經(jīng)執(zhí)行了 4000 多分鐘，我們服務(wù)器也就啟動(dòng)了兩天，可見這兩天它們是一刻也沒閑著！那它們究竟在干什么呢？我們可以使用命令：thread id，查看線程堆棧。

[arthas@384]$ thread 108 "http-nio-7001-exec-10" Id=108 cpuUsage=51% RUNNABLEat c.g.c.c.HashBiMap.seekByKey(HashBiMap.java)at c.g.c.c.HashBiMap.put(HashBiMap.java:270)at c.g.c.c.HashBiMap.forcePut(HashBiMap.java:263)at c.y.r.j.o.OaInfoManager.syncUserCache(OaInfoManager.java:159)

也可以使用 thread -n 3 命令打印出 CPU 占比最高的前三個(gè)線程，這差不多是 > top -Hp> ?&?> printf> ?&?> jstack> ?三令合一的效果了>

可以看到，這個(gè)線程一直在執(zhí)行 HashBiMap.seekByKey 方法（可以重復(fù)執(zhí)行幾次 thread id 確保該線程執(zhí)行的方法沒有時(shí)刻在變化），造成這個(gè)問題一般有兩個(gè)原因：

seekByKey 方法被循環(huán)調(diào)用

seekByKey 內(nèi)部有死循環(huán)

先看一下是不是第一種，我們使用 tt 命令監(jiān)聽一下這個(gè)方法的調(diào)用情況：

tt -t com.google.common.collect.HashBiMap seekByKey -n 100

注意：在線上執(zhí)行這個(gè)命令的時(shí)候，一定要記得加上 -n 參數(shù)，否則線上巨大的流量可能會(huì)瞬間撐爆你的 JVM 內(nèi)存執(zhí)行結(jié)果顯示，seekByKey 方法并沒有被一直調(diào)用，那大概率是 seekByKey 方法內(nèi)部有死循環(huán)。看下這個(gè)方法內(nèi)部的邏輯，我們可以使用 jad com.google.common.collect.HashBiMap seekByKey 命令反編譯這個(gè)方法，這樣做的好處是顯得比較高端，不過我還是打算直接找到源碼，說不定還有注釋。源碼如下：

private BiEntry<K, V> seekByKey(@Nullable Object key, int keyHash) {for (BiEntry<K, V> entry = hashTableKToV[keyHash & mask];entry != null;entry = entry.nextInKToVBucket) {if (keyHash == entry.keyHash && Objects.equal(key, entry.key)) {return entry;}}return null;}

然后并沒有注釋，還好這個(gè)方法邏輯比較簡(jiǎn)單，也很容易看懂。

通過 hash 找到 bucket，每個(gè) bucket 是一個(gè)鏈表；

遍歷鏈表，找到這個(gè) key 對(duì)應(yīng)的 entry。這里要留意下 entry 的下一個(gè)節(jié)點(diǎn)是 nextInKToVBucket，后文中會(huì)用到。

發(fā)生了死循環(huán)，我們猜想可能是因?yàn)檫@個(gè)鏈表有環(huán)路。那么有沒有辦法驗(yàn)證這個(gè)猜想呢？答案是有！那么如何驗(yàn)證呢？首先我們要獲得這個(gè) HashBiMap 對(duì)象，以便于查詢對(duì)象里的數(shù)據(jù)。獲得這個(gè)對(duì)象有很多辦法，比如監(jiān)聽這個(gè)對(duì)象的某個(gè)方法，然后主動(dòng)觸發(fā)這個(gè)方法。這里向大家介紹一種更為通用的方法，這個(gè)方法在 SpringMVC 程序里非常好用。因?yàn)槲覀兪?SpringMVC 應(yīng)用，所有請(qǐng)求都會(huì)被 RequestMappingHandlerAdapter 攔截，我們通過 tt 命令，監(jiān)聽 invokeHandlerMethod 的執(zhí)行，然后在頁面隨便點(diǎn)點(diǎn)，就會(huì)得到以下內(nèi)容：

[arthas@384]$ tt -t org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter invokeHandlerMethod -n 10 Press Q or Ctrl+C to abort. Affect(class-cnt:1 , method-cnt:1) cost in 622 ms.INDEX COST(ms) OBJECT CLASS METHOD ------------------------------------------------------------------------------------1000 481.203383 0x481eb705 RequestMappingHandlerAdapter invokeHandlerMethod1001 3.432024 0x481eb705 RequestMappingHandlerAdapter invokeHandlerMethod ...

tt 命令會(huì)記錄方法調(diào)用時(shí)的所有入?yún)⒑头祷刂怠伋龅漠惓！?duì)象本身等數(shù)據(jù)。INDEX 字段代表著一次調(diào)用，后續(xù)tt還有很多命令都是基于此編號(hào)指定記錄操作。

我們可以通過 -i 參數(shù)后邊跟著對(duì)應(yīng)的 INDEX 編號(hào)查看這條記錄的詳細(xì)信息。再通過 -w 參數(shù)，指定一個(gè) OGNL 表達(dá)式，查找相關(guān)對(duì)象：

[arthas@384]$ tt -i 1000 -w 'target.getApplicationContext()' @AnnotationConfigServletWebServerApplicationContext[reader=@AnnotatedBeanDefinitionReader[org.springframework.context.annotation.AnnotatedBeanDefinitionReader@50294e97],scanner=@ClassPathBeanDefinitionScanner[org.springframework.context.annotation.ClassPathBeanDefinitionScanner@5eeeaae2],annotatedClasses=@LinkedHashSet[isEmpty=true;size=0],basePackages=null,

OGNL 使用文檔：https://commons.apache.org/proper/commons-ognl/language-guide.html

Arthas 會(huì)把當(dāng)前執(zhí)行的對(duì)象放到 target 變量中，通過 target.getApplicationContext() 就得到了 SpringContext 對(duì)象，然后，我們就可以為所欲為了!

接下來我們需要用 OGNL 寫一個(gè)函數(shù)，來實(shí)現(xiàn)鏈表的環(huán)路檢測(cè)，在 OGNL 里寫一段環(huán)路檢測(cè)代碼里是不太容易的，這里我用了一個(gè)取巧的偽實(shí)現(xiàn)。

#loopCnt=0, #foundCycle=:[ #this == null ? false :#loopCnt > 50 ? true :(#loopCnt = #loopCnt + 1,#foundCycle(#this.nextInKToVBucket))]

因?yàn)槲抑酪粋€(gè) bucket 不太可能有 50 個(gè)以上的節(jié)點(diǎn)，所以就通過遍歷次數(shù)是否大于 50 來判斷是否有環(huán)路。

完整的命令：

tt -i 1000 -w ‘target.getApplicationContext().getBean(“oaInfoManager”).userCache.entrySet().{delegate}.{^ #loopCnt = 0,#foundCycle = :[ #this == null ? false : #loopCnt > 50 ? true : (#loopCnt = #loopCnt + 1, #foundCycle(#this.nextInKToVBucket))], #foundCycle(#this)}.get(0)’ -x 2

命令解析：

獲取 HashBiMap 對(duì)象：target.getApplicationContext().getBean("oaInfoManager").userCache

遍歷所有 entry，取出第一個(gè)有環(huán)路的 entry

-x 參數(shù)指定展開層級(jí)，我們需要將這個(gè)參數(shù)設(shè)置的比環(huán)要大一些，才能確保可以發(fā)現(xiàn)環(huán)路。這里我們的環(huán)路非常小，所以設(shè)置成了 2

執(zhí)行結(jié)果如下：

@BiEntry[key=@String[張三],value=@Long[1111],nextInKToVBucket=@BiEntry[key=@String[李四],value=@Long[2222],nextInKToVBucket=@BiEntry[張三=1111]] ]

可以看到是有 張三->李四->張三 這樣一個(gè)環(huán)路。至此，造成死循環(huán)的原因確定了下來。結(jié)合兩個(gè)線程幾乎同時(shí)啟動(dòng)，又同時(shí)在執(zhí)行 HashBiMap.forcePut 方法，容易想到是因?yàn)椴l(fā)導(dǎo)致了數(shù)據(jù)的不一致，這一點(diǎn)也可以驗(yàn)證，不過由于篇幅有限，這里就不再贅述。找到了問題，就成功了 99%，解決這個(gè)問題的方法非常簡(jiǎn)單，就是對(duì) syncUserCache 方法加一個(gè) synchronized 關(guān)鍵字！

結(jié)語

這次遇到的問題并不復(fù)雜，用 jstack 命令也可以解決的了。但我們希望通過這樣一個(gè)案例，向大家展示 Arthas 一些強(qiáng)大的功能，幫助大家打開思路，未來在遇到更復(fù)雜場(chǎng)景時(shí)，可以多一些趁手的工具！

Arthas 征文活動(dòng)火熱進(jìn)行中

Arthas 官方正在舉行征文活動(dòng)，如果你有：

• 使用 Arthas 排查過的問題
• 對(duì) Arthas 進(jìn)行源碼解讀
• 對(duì) Arthas 提出建議
• 不限，其它與 Arthas 有關(guān)的內(nèi)容

歡迎參加征文活動(dòng)，還有獎(jiǎng)品拿哦~點(diǎn)擊投稿

“阿里巴巴云原生關(guān)注微服務(wù)、Serverless、容器、Service Mesh 等技術(shù)領(lǐng)域、聚焦云原生流行技術(shù)趨勢(shì)、云原生大規(guī)模的落地實(shí)踐，做最懂云原生開發(fā)者的公眾號(hào)。”

總結(jié)

以上是生活随笔為你收集整理的利用 Arthas 精准定位 Java 应用 CPU 负载过高问题的全部?jī)?nèi)容，希望文章能夠幫你解決所遇到的問題。

如果覺得生活随笔網(wǎng)站內(nèi)容還不錯(cuò)，歡迎將生活随笔推薦給好友。