Arthas 官方社群正在舉行徵文活動，參加即有獎品拿哦~[點選投稿](http://alibabacloud.mikecrm.com/9khcRrs)

作者 | 張雲翔

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

以前碰到類似問題，可能會考慮使用 `top -Hp` 加 `jstack` 命令去排查，雖然能大致定位到問題範圍，但有效資訊還是太少了，多數時候還是要靠猜。今天向大家推薦一款更高效更精準的工具：`Arthas`！Arthas 是 Alibaba 開源的 Java 診斷工具，能夠幫助我們快速定位線上問題。基本的安裝使用可以參考官方文件：[https://alibaba.github.io/arthas](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](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 有關的內容

歡迎參加徵文活動，還有獎品拿哦~[點選投稿](http://alibabacloud.mikecrm.com/9khcRrs)

> “[阿里巴巴雲原生](http://mp.weixin.qq.com/s?__biz=MzUzNzYxNjAzMg==&mid=2247489867&idx=1&sn=1e52e16f370541de77f84d4a3b100a2d&chksm=fae51284cd929b926bbed215cd609da749ba265693ebc08b1af1f027bf8a1b0e0d9aa682d99b&token=277022989&lang=zh_CN#rd)關注微服務、Serverless、容器、Service Mesh 等技術領域、聚焦雲原生流行技術趨勢、雲原生大規模的落地實踐，做最懂雲原生開發者的公眾號。”</k></k>

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

相關文章