利用 Arthas 精準定位 Java 應用 CPU 負載過高問題

雲栖号資訊：【 點選檢視更多行業資訊

】

在這裡您可以找到不同行業的第一手的上雲資訊，還在等什麼，快來！

最近我們線上有個應用伺服器有點上頭，CPU總能跑到99%，我尋思着它流量也不大啊，為啥能把自己整這麼累？于是我登上這台伺服器，看看它到底在幹啥！

以前碰到類似問題，可能會考慮使用 top -Hp 加 jstack 指令去排查，雖然能大緻定位到問題範圍，但有效資訊還是太少了，多數時候還是要靠猜。今天向大家推薦一款更高效更精準的工具：Arthas！Arthas 是 Alibaba 開源的 Java 診斷工具，能夠幫助我們快速定位線上問題。基本的安裝使用可以參考官方文檔：

https://alibaba.github.io/arthas

這次我們利用它來排查 CPU 負載高的問題。CPU 負載過高一般是某個或某幾個線程有問題，是以我們嘗試使用第一個指令：thread，這個指令會顯示所有線程的資訊，并且把 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 資源幾乎被前兩個線程占滿，并且已經執行了 4000 多分鐘，我們伺服器也就啟動了兩天，可見這兩天它們是一刻也沒閑着！那它們究竟在幹什麼呢？我們可以使用指令：thread id，檢視線程堆棧。

[arthas@384]$ thread 108 "http-nio-7001-exec-10" Id=108 cpuUsage=51% RUNNABLE
at 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 占比最高的前三個線程，這差不多是 > top -Hp> & > printf> & > jstack> 三令合一的效果了>

可以看到，這個線程一直在執行 HashBiMap.seekByKey 方法（可以重複執行幾次 thread id 確定該線程執行的方法沒有時刻在變化），造成這個問題一般有兩個原因：

• seekByKey 方法被循環調用
• seekByKey 内部有死循環

先看一下是不是第一種，我們使用 tt 指令監聽一下這個方法的調用情況：

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

注意：線上上執行這個指令的時候，一定要記得加上 -n 參數，否則線上巨大的流量可能會瞬間撐爆你的 JVM 記憶體執行結果顯示，seekByKey 方法并沒有被一直調用，那大機率是 seekByKey 方法内部有死循環。看下這個方法内部的邏輯，我們可以使用 jad com.google.common.collect.HashBiMap seekByKey 指令反編譯這個方法，這樣做的好處是顯得比較高端，不過我還是打算直接找到源碼，說不定還有注釋。源碼如下：

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;
}
           

然後并沒有注釋，還好這個方法邏輯比較簡單，也很容易看懂。

1.通過 hash 找到 bucket，每個 bucket 是一個連結清單；

2.周遊連結清單，找到這個 key 對應的 entry。這裡要留意下 entry 的下一個節點是 nextInKToVBucket，後文中會用到。

發生了死循環，我們猜想可能是因為這個連結清單有環路。那麼有沒有辦法驗證這個猜想呢？答案是有！那麼如何驗證呢？首先我們要獲得這個 HashBiMap 對象，以便于查詢對象裡的資料。獲得這個對象有很多辦法，比如監聽這個對象的某個方法，然後主動觸發這個方法。這裡向大家介紹一種更為通用的方法，這個方法在 SpringMVC 程式裡非常好用。因為我們是 SpringMVC 應用，所有請求都會被 RequestMappingHandlerAdapter 攔截，我們通過 tt 指令，監聽 invokeHandlerMethod 的執行，然後在頁面随便點點，就會得到以下内容：

[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 invokeHandlerMethod
1001 3.432024 0x481eb705 RequestMappingHandlerAdapter invokeHandlerMethod
...
           

tt 指令會記錄方法調用時的所有入參和傳回值、抛出的異常、對象本身等資料。INDEX 字段代表着一次調用，後續tt還有很多指令都是基于此編号指定記錄操作。

我們可以通過 -i 參數後邊跟着對應的 INDEX 編号檢視這條記錄的詳細資訊。再通過 -w 參數，指定一個 OGNL 表達式，查找相關對象：

[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,
           

Arthas 會把目前執行的對象放到 target 變量中，通過 target.getApplicationContext() 就得到了 SpringContext 對象，然後，我們就可以為所欲為了!

接下來我們需要用 OGNL 寫一個函數，來實作連結清單的環路檢測，在 OGNL 裡寫一段環路檢測代碼裡是不太容易的，這裡我用了一個取巧的僞實作。

因為我知道一個 bucket 不太可能有 50 個以上的節點，是以就通過周遊次數是否大于 50 來判斷是否有環路。

完整的指令：

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 對象：target.getApplicationContext().getBean("oaInfoManager").userCache

周遊所有 entry，取出第一個有環路的 entry

-x 參數指定展開層級，我們需要将這個參數設定的比環要大一些，才能確定可以發現環路。這裡我們的環路非常小，是以設定成了 2

執行結果如下：

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

可以看到是有 張三->李四->張三 這樣一個環路。至此，造成死循環的原因确定了下來。結合兩個線程幾乎同時啟動，又同時在執行 HashBiMap.forcePut 方法，容易想到是因為并發導緻了資料的不一緻，這一點也可以驗證，不過由于篇幅有限，這裡就不再贅述。找到了問題，就成功了 99%，解決這個問題的方法非常簡單，就是對 syncUserCache 方法加一個 synchronized 關鍵字！

結語

這次遇到的問題并不複雜，用 jstack 指令也可以解決的了。但我們希望通過這樣一個案例，向大家展示 Arthas 一些強大的功能，幫助大家打開思路，未來在遇到更複雜場景時，可以多一些趁手的工具！

【雲栖号線上課堂】每天都有産品技術專家分享！

課程位址：

https://yqh.aliyun.com/live

立即加入社群，與專家面對面，及時了解課程最新動态！

【雲栖号線上課堂 社群】

https://c.tb.cn/F3.Z8gvnK

原文釋出時間：2020-06-11

本文作者：張雲翔

本文來自：“

dockone

”，了解相關資訊可以關注“dockone”