作者 | 介龍平，英文名 leo，碼農一枚

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

## 1. 異常突起

HBase 叢集的某一個 RegionServer 的 CPU 使用率突然飆升到百分之百，單獨重啟該 RegionServer 之後，CPU 的負載依舊會逐漸攀上頂峰。多次重啟叢集之後，CPU 滿載的現象依然會復現，且會持續居高不下，慢慢地該 RegionServer 就會宕掉，慢慢地 HBase 叢集就完犢子了。

## 2. 異常之上的現象

CDH 監控頁面來看，除 CPU 之外的幾乎所有核心指標都是正常的，磁碟和網路 IO 都很低，記憶體更是充足，壓縮佇列，重新整理佇列也是正常的。

![1.png](https://ucc.alicdn.com/pic/developer-ecology/bb8a3baf3a6a4920946583520404e7ea.png)

普羅米修斯的監控也是類似這樣的，就不貼圖了。

監控指標裡的數字，只能直觀地告訴我們現象，不能告訴我們異常的起因。因此我們的第二反應是看日誌。

![2.png](https://ucc.alicdn.com/pic/developer-ecology/343f5a12276d46b2830d37a85e84f515.png)
（企業微信截圖）

與此同時，日誌中還有很多類似這樣的干擾輸出。

![3.png](https://ucc.alicdn.com/pic/developer-ecology/216c5be4a1c1419d8a0b4bc9e47c6163.png)

後來發現這樣的輸出只是一些無關緊要的資訊，對分析問題沒有任何幫助，甚至會干擾我們對問題的定位。

但是，日誌中大量 scan responseTooSlow 的警告資訊，似乎在告訴我們，HBase 的 Server 內部正在發生著大量耗時的 scan 操作，這也許就是 CPU 負載高的元兇。可是，由於各種因素的作用，我們當時的關注點並沒有在這個上面，因為這樣的資訊，我們在歷史的時間段裡也頻繁撞見。

## 3. 初識 arthas

監控和日誌都不能讓我們百分百確定 CPU 負載高是由哪些操作引起的，我們用 top 命令也只能看到 HBase 這個程式消耗了很多 CPU，就像下圖看到的這樣。

![4.png](https://ucc.alicdn.com/pic/developer-ecology/929351a866ac4cb6b99db955fbce3766.png)

如果不做進一步分析，你仍然不知道，問題出現在 HBase 相關程式下的哪些執行執行緒。Java 中分析程式的命令，可以使用 `jstack` 或 `jstat gcutil` 等。但是，今天要介紹的主角不是這倆，甚至不是 `async-profiler`，而是 `arthas`。`async-profiler` 雖然也是一個很強大的工具，但是 `arthas` 包含了它，且功能更強大，堪稱神器。

`arthas` 很早以前就聽說過，起初以為它只能用來分析 WEB 應用，例如 Spring Boot，這兩天仔細翻看其官方文件之後，才覺得自己是多麼的無知。`arthas` 的相關介紹和入門使用，請參考其文件，它的官方文件比任何第三方資料都詳細和友好。

- [https://github.com/alibaba/arthas](https://github.com/alibaba/arthas)
- 阿爾薩斯官方文件
- [https://github.com/jvm-profiling-tools/async-profiler](https://github.com/jvm-profiling-tools/async-profiler)

## 4. 用 arthas 來分析 HBase 的異常程式

### 4.1 執行 arthas

```
java -jar /data/arthas/arthas-boot.jar  --target-ip 0.0.0.0
```

- --target-ip 預設 127.0.0.1，此處賦值為 0.0.0.0 是為了使用 webconsole

### 4.2 arthas 執行成功的介面

![5.png](https://ucc.alicdn.com/pic/developer-ecology/bbdc1605526046af8a0a4c3320208f79.png)

命令 top 定位到的異常的 HBase 程式 ID 是 1214，該程式就是 HRegionServer 的程式。輸入序號 1，回車，就進入了監聽該程式的命令列介面。

### 4.3 dashboard

![6.png](https://ucc.alicdn.com/pic/developer-ecology/d50663aa8f7943d68a7ecb4a08fdb4a1.png)

執行 dashboard 命令回車，就可以檢視該程式佔用資源的總體情況，可以從圖中看到，ID 為 59 的執行緒，佔用的 CPU 最高。

### 4.4 thread

![7.png](https://ucc.alicdn.com/pic/developer-ecology/b9e4e7765b2849cea038db3612d33cc8.png)

輸入 thread 命令回車，檢視該程式下所有執行緒的執行情況。

### 4.5 thread -n 3

![8.png](https://ucc.alicdn.com/pic/developer-ecology/36e07de25bc44af48748c7c33bcec247.png)

輸出資源佔用前三名的執行緒。

### 4.6 thread -n 3 -i 5000

![9.png](https://ucc.alicdn.com/pic/developer-ecology/d5975b336fb544ff86ad0361fa064262.png)

單位時間為 5 秒內，資源佔用前三名的執行緒。

### 4.7 使用async-profiler生成火焰圖

生成火焰圖的最簡單命令。

```
profiler start
```

隔一段時間，大概三十秒。

```
profiler stop
```

![10.png](https://ucc.alicdn.com/pic/developer-ecology/774cc9fdd3b24405aecf1be32afdf53d.png)

在 web console 裡檢視。

![11.png](https://ucc.alicdn.com/pic/developer-ecology/44cfa24c596043ed905e775d60b55c7f.png)

關於火焰圖的入門級知識：

檢視 jvm 程式 cpu 火焰圖工具。

火焰圖裡很清楚地定位到 CPU 時間佔用最高的執行緒是綠框最長的那些執行緒，也就是 scan 操作。

## 5. scan 操作引起的 CPU 負載過高

透過以上的程式分析，我們最終可以確定，scan 操作的發生，導致 CPU 負載很高。我們查詢 HBase 的 API 基於 happybase 封裝而成，[https://happybase.readthedocs.io/en/latest/](https://happybase.readthedocs.io/en/latest/)

其實常規的 scan 操作是能正常返回結果的，發生異常查詢的表也不是很大，所以我們排除了熱點的可能。抽象出來業務方的查詢邏輯是：

```
from happybase.connection import Connection
import time
start = time.time()
con = Connection(host='ip', port=9090, timeout=3000)
table = con.table("table_name")
try:
    res = list(table.scan(filter="PrefixFilter('273810955|')",
                      row_start='\x0f\x10&R\xca\xdf\x96\xcb\xe2\xad7$\xad9khE\x19\xfd\xaa\x87\xa5\xdd\xf7\x85\x1c\x81ku ^\x92k',
                      limit=3))
except Exception as e:
    pass
end = time.time()
print 'timeout: %d' % (end - start)
```

PrefixFilter 和 row_start 的組合是為了實現分頁查詢的需求，row_start 的一堆亂碼字元，是加密的一個 user_id，裡面有特殊字元。日誌中看到，所有的耗時查詢，都有此類亂碼字元的傳參。於是，我們猜想，查詢出現的異常與這些亂碼字元有關。

但是，後續測試復現的時候又發現。

```
# 會超時
  res = list(table.scan(filter="PrefixFilter('273810955|')",
                      row_start='27', limit=3))
  # 不會超時
  res = list(table.scan(filter="PrefixFilter('273810955|')",
                      row_start='27381095', limit=3))
```

也就是，即使不是亂碼字元傳參，filter 和 row_start 組合異常，也會導致 CPU 異常的高，row_start 指定的過小，小於字首，資料掃描的範圍估計就會變大，類似觸發了全表掃描，CPUload 勢必會變大。

## 6. 頻繁建立連線或使用執行緒池造成 scan 執行緒持續增長

我們操作 HBase 的公共程式碼是由 happybase 封裝而成，其中還用到了 happybase 的執行緒池，在我們更深入的測試中又發現了一個現象，當我們使用連線池或在迴圈中重複建立連線時，然後用 arthas 監控執行緒情況，發現 scan 的執行緒會很嚴重，測試程式碼如下：

### 6.1 連線在迴圈外部建立，重複使用

```
from happybase.connection import Connection
import time
con = Connection(host='ip', port=9090, timeout=2000)
table = con.table("table")
for i in range(100):
    try:
          start = time.time()
        res = list(table.scan(filter="PrefixFilter('273810955|')",
                              row_start='\x0f\x10&R\xca\xdf\x96\xcb\xe2\xad7$\xad9khE\x19\xfd\xaa\x87\xa5\xdd\xf7\x85\x1c\x81ku ^\x92k',
                              limit=3))
    except Exception as e:
        pass
    end = time.time()
    print 'timeout: %d' % (end - start)
```

程式開始執行時，可以開啟 arthas 進入到 HRegionServer 程式的監控，執行 thread 命令，檢視此時的執行緒使用情況：

![12.png](https://ucc.alicdn.com/pic/developer-ecology/abd066fe16404ceba3c47d17c800a86f.png)

![13.png](https://ucc.alicdn.com/pic/developer-ecology/661fa28e51c7490cb29276ce5f4d63d1.png)

小部分在執行，大部分在等待。此時，CPU 的負載情況：

![14.png](https://ucc.alicdn.com/pic/developer-ecology/717d252e5f734f5d81d27142a444e243.png)

### 6.2 迴圈在內部頻繁建立然後使用

程式碼如下：

```
from happybase.connection import Connection
import time
for i in range(100):
    try:
        start = time.time()
        con = Connection(host='ip', port=9090, timeout=2000)
        table = con.table("table")
        res = list(table.scan(filter="PrefixFilter('273810955|')",
                              row_start='\x0f\x10&R\xca\xdf\x96\xcb\xe2\xad7$\xad9khE\x19\xfd\xaa\x87\xa5\xdd\xf7\x85\x1c\x81ku ^\x92k',
                              limit=3))
    except Exception as e:
        pass
    end = time.time()
    print 'timeout: %d' % (end - start)
```

下圖中可以看到開始 RUNNING 的執行緒越來越多，CPU 的消耗也越來越大。

![15.png](https://ucc.alicdn.com/pic/developer-ecology/f36a1f57b2434ce6bf3ad11a981f2249.png)

![16.png](https://ucc.alicdn.com/pic/developer-ecology/d790c69eb52843bf82f3408447fd2f85.png)

此時 CPU 的使用情況，由剛才的較為平穩，陡然上升：

![17.png](https://ucc.alicdn.com/pic/developer-ecology/fb67cb6ac2904c228315ef179c4bca75.png)

### 6.3 連線池的方式訪問 HBase

CPU 被之前的實驗拉高，重啟下叢集使 CPU 的狀態恢復到之前平穩的狀態。然後繼續我們的測試，測試程式碼：

**沒有超時時間**

```
from happybase import ConnectionPool
import time
pool = ConnectionPool(size=1, host='ip', port=9090)
for i in range(100):
    start = time.time()
    try:
        with pool.connection(2000) as con:
            table = con.table("table")
            res = list(table.scan(filter="PrefixFilter('273810955|')",
                                  row_start='\x0f\x10&R\xca\xdf\x96\xcb\xe2\xad7$\xad9khE\x19\xfd\xaa\x87\xa5\xdd\xf7\x85\x1c\x81ku ^\x92k',
                                  limit=3))
    except Exception as e:
        pass
    end = time.time()
    print 'timeout: %d' % (end - start)
```

如果不指定超時時間，會只有一個執行緒持續執行，因為我的連線池設定為 1。

![18.png](https://ucc.alicdn.com/pic/developer-ecology/42306d21a9854be4a88460e160d85911.png)

CPU 的負載也不是太高，如果我的連線池設定的更大，或者我的併發加大，那麼這些耗時 scan 的執行緒應該會更多，CPU 使用率也會飆升。

![19.png](https://ucc.alicdn.com/pic/developer-ecology/1f17871aa1a34054a67a5db72c52b8f1.png)

**指定超時時間**

```
from happybase import ConnectionPool
import time
pool = ConnectionPool(size=1, host='ip', port=9090, timeout=2000)
for i in range(100):
    start = time.time()
    try:
        with pool.connection(2000) as con:
            table = con.table("table")
            res = list(table.scan(filter="PrefixFilter('273810955|')",
                                  row_start='\x0f\x10&R\xca\xdf\x96\xcb\xe2\xad7$\xad9khE\x19\xfd\xaa\x87\xa5\xdd\xf7\x85\x1c\x81ku ^\x92k',
                                  limit=3))
    except Exception as e:
        pass
    end = time.time()
    print 'timeout: %d' % (end - start)
```

此次測試中，我指定了連線池中的超時時間，期望的是，連線超時，及時斷開，繼續下一次耗時查詢。此時，服務端處理 scan 請求的執行緒情況：

![20.png](https://ucc.alicdn.com/pic/developer-ecology/150651db778c42d190a83b50f42f3bb1.png)

服務端用於處理 scan 請求的 RUNNING 狀態的執行緒持續增長，並耗費大量的 CPU。

![21.png](https://ucc.alicdn.com/pic/developer-ecology/52498b1729234c19a18a055652ec96d3.png)

## 7. hbase.regionserver.handler.count

![22.png](https://ucc.alicdn.com/pic/developer-ecology/5b84fed8c3a449e5a97c6507e44c3cfd.png)

參考大神的部落格，以及自己對這個引數的理解，每一個客戶端發起的 RPC 請求（讀或寫），傳送給服務端的時候，服務端就會有一個執行緒池，專門負責處理這些客戶端的請求，這個執行緒池可以保證同一時間點有 30 個執行緒可執行，剩餘請求要麼阻塞，要麼被塞進佇列中等待被處理，scan 請求撐滿了服務端的執行緒池，大量的耗時操作，把 CPU 資源消耗殆盡，其餘常規的讀寫請求也勢必大受影響，慢慢叢集就完犢子了。

## 8. 控制 scan 請求佔用很小的佇列

首先，這個 `hbase.regionserver.handler.count` 的引數不能被調小，如果太小，叢集併發高時，讀寫延時必高，因為大部分請求都在排隊。理想情況是，讀和寫佔用不同的執行緒池，在處理讀請求時，scan 和 get 分別佔用不同的執行緒池，實現執行緒池資源隔離。如果是我的話，第一反應可能也會簡單、粗略地搞仨執行緒池，寫執行緒池，get 執行緒池、scan 執行緒池。scan 執行緒池分配很小的核心執行緒，讓其佔用很小的資源，限制其無限擴張。但是真實的情況是這樣嗎？暫時，我還沒仔細研究原始碼，HBase 提供瞭如下引數，可以滿足讀寫資源分離的需求。以下內容摘自 HBase 官網文件，翻譯為谷歌翻譯。[https://hbase.apache.org/2.1/book.html](https://hbase.apache.org/2.1/book.html)

**hbase.regionserver.handler.count**

```
描述
在RegionServer上旋轉的RPC偵聽器例項數。主機將相同的屬性用於主機處理程式的計數。過多的處理程式可能適得其反。使它成為CPU計數的倍數。如果大多數情況下是隻讀的，則處理程式計數接近cpu計數的效果很好。從兩倍的CPU計數開始，然後從那裡進行調整。
預設
30
```

**hbase.ipc.server.callqueue.handler.factor**

```
描述
確定呼叫佇列數量的因素。值為0表示在所有處理程式之間共享一個佇列。值為1表示每個處理程式都有自己的佇列。
預設
0.1
```

**hbase.ipc.server.callqueue.read.ratio**

```
描述
將呼叫佇列劃分為讀寫佇列。指定的間隔（應在0.0到1.0之間）將乘以呼叫佇列的數量。值為0表示不拆分呼叫佇列，這意味著讀取和寫入請求都將被推送到同一組佇列中。小於0.5的值表示讀佇列少於寫佇列。值為0.5表示將有相同數量的讀取和寫入佇列。大於0.5的值表示將有比寫佇列更多的讀佇列。值1.0表示除一個佇列外的所有佇列均用於排程讀取請求。示例：給定呼叫佇列的總數為10，讀比率為0表示：10個佇列將包含兩個讀/寫請求。read.ratio為0.3表示：3個佇列將僅包含讀取請求，而7個佇列將僅包含寫入請求。read.ratio為0.5表示：5個佇列僅包含讀取請求，而5個佇列僅包含寫入請求。read.ratio為0.8表示：8個佇列將僅包含讀取請求，而2個佇列將僅包含寫入請求。read.ratio為1表示：9個佇列將僅包含讀取請求，而1個佇列將僅包含寫入請求。
預設
0
```

**hbase.ipc.server.callqueue.scan.ratio**

```
描述
給定讀取呼叫佇列的數量（根據呼叫佇列總數乘以callqueue.read.ratio計算得出），scan.ratio屬性會將讀取呼叫佇列分為小讀取佇列和長讀取佇列。小於0.5的值表示長讀佇列少於短讀佇列。值為0.5表示將有相同數量的短讀和長讀佇列。大於0.5的值表示長讀取佇列比短讀取佇列多。值為0或1表示使用相同的佇列進行獲取和掃描。示例：假設讀取呼叫佇列的總數為8，則scan.ratio為0或1表示：8個佇列將同時包含長讀取請求和短讀取請求。scan.ratio為0.3表示：2個佇列將僅包含長讀請求，而6個佇列將僅包含短讀請求。scan.ratio為0.5表示：4個佇列將僅包含長讀請求，而4個佇列將僅包含短讀請求。scan.ratio為0.8表示：6個佇列將僅包含長讀請求，而2個佇列將僅包含短讀請求。
預設
0
```

這幾個引數的作用官網解釋的還挺詳細，按照其中的意思，配置一定比例，就可以達到讀寫佇列，get 和 scan 佇列分離的目的，但是，調配引數後，繼續如上測試，發現，並不難控制 RUNNING 的執行緒的數量，發現沒毛用。

這裡有一個疑問，佇列和我所理解的執行緒池直接到底是什麼關係？是否是一個東西？這個之後需要觀其原始碼，窺其本質。

## 9. 總結

囉囉嗦嗦總算把定位問題的整個過程記錄了下來，其實文字描述的還不算很詳盡，只是儘可能還原當時的場景和梳理問題的大體思維流程，免得以後遺忘，同時也期望各位同行能從我這裡受到點啟發，期間也受到了不少大神的提點，在此也特別感謝各方大佬的幫助。

# 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=1335200991&lang=zh_CN#rd)關注微服務、Serverless、容器、Service Mesh 等技術領域、聚焦雲原生流行技術趨勢、雲原生大規模的落地實踐，做最懂雲原生開發者的公眾號。”

用 Arthas 神器來診斷 HBase 異常程式

相關文章