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

Arthas 官方社區正在舉行徵文活動，參加即有獎品拿哦~點擊投稿

做者 | 張雲翔

最近咱們線上有個應用服務器有點上頭，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 確保該線程執行的方法沒有時刻在變化），形成這個問題通常有兩個緣由：

1. seekByKey 方法被循環調用
2. 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,

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

Arthas 會把當前執行的對象放到 target 變量中，經過 target.getApplicationContext() 就獲得了 SpringContext 對象，而後，咱們就能夠隨心所欲了!

接下來咱們須要用 OGNL 寫一個函數，來實現鏈表的環路檢測，在 OGNL 裏寫一段環路檢測代碼裏是不太容易的，這裏我用了一個取巧的僞實現。

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

由於我知道一個 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

命令解析：

1. 獲取 HashBiMap 對象：target.getApplicationContext().getBean("oaInfoManager").userCache
2. 遍歷全部 entry，取出第一個有環路的 entry
3. -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 一些強大的功能，幫助你們打開思路，將來在遇到更復雜場景時，能夠多一些趁手的工具！

Arthas 徵文活動火熱進行中

Arthas 官方正在舉行徵文活動，若是你有：

• 使用 Arthas 排查過的問題
• 對 Arthas 進行源碼解讀
• 對 Arthas 提出建議
• 不限，其它與 Arthas 有關的內容

  歡迎參加徵文活動，還有獎品拿哦~點擊投稿

「 阿里巴巴雲原生關注微服務、Serverless、容器、Service Mesh 等技術領域、聚焦雲原生流行技術趨勢、雲原生大規模的落地實踐，作最懂雲原生開發者的公衆號。」