![](https://img.laitimes.com/img/__Qf2AjLwojIjJCLyojI0JCLicmbw5iZ3czN0ImMzEWM3EDMmJGM0kjNzADOzUmN0QzN3QDOk9CX0JXZ252bj91Ztl2Lc52YucWbp5GZzNmLn9Gbi1yZtl2Lc9CX6MHc0RHaiojIsJye.png)
作者 | 介龍平,英文名 leo,碼農一枚
【Arthas 官方社群正在舉行征文活動,參加即有獎品拿~點選投稿】1. 異常突起
HBase 叢集的某一個 RegionServer 的 CPU 使用率突然飙升到百分之百,單獨重新開機該 RegionServer 之後,CPU 的負載依舊會逐漸攀上頂峰。多次重新開機叢集之後,CPU 滿載的現象依然會複現,且會持續居高不下,慢慢地該 RegionServer 就會宕掉,慢慢地 HBase 叢集就完犢子了。
2. 異常之上的現象
CDH 監控頁面來看,除 CPU 之外的幾乎所有核心名額都是正常的,磁盤和網絡 IO 都很低,記憶體更是充足,壓縮隊列,重新整理隊列也是正常的。
普羅米修斯的監控也是類似這樣的,就不貼圖了。
監控名額裡的數字,隻能直覺地告訴我們現象,不能告訴我們異常的起因。是以我們的第二反應是看日志。
(企業微信截圖)
與此同時,日志中還有很多類似這樣的幹擾輸出。
後來發現這樣的輸出隻是一些無關緊要的資訊,對分析問題沒有任何幫助,甚至會幹擾我們對問題的定位。
但是,日志中大量 scan responseTooSlow 的警告資訊,似乎在告訴我們,HBase 的 Server 内部正在發生着大量耗時的 scan 操作,這也許就是 CPU 負載高的元兇。可是,由于各種因素的作用,我們當時的關注點并沒有在這個上面,因為這樣的資訊,我們在曆史的時間段裡也頻繁撞見。
3. 初識 arthas
監控和日志都不能讓我們百分百确定 CPU 負載高是由哪些操作引起的,我們用 top 指令也隻能看到 HBase 這個程序消耗了很多 CPU,就像下圖看到的這樣。
如果不做進一步分析,你仍然不知道,問題出現在 HBase 相關程序下的哪些執行線程。Java 中分析程序的指令,可以使用
jstack
或
jstat gcutil
等。但是,今天要介紹的主角不是這倆,甚至不是
async-profiler
,而是
arthas
。
async-profiler
雖然也是一個很強大的工具,但是
arthas
包含了它,且功能更強大,堪稱神器。
arthas
很早以前就聽說過,起初以為它隻能用來分析 WEB 應用,例如 Spring Boot,這兩天仔細翻看其官方文檔之後,才覺得自己是多麼的無知。
arthas
的相關介紹和入門使用,請參考其文檔,它的官方文檔比任何第三方資料都詳細和友好。
- https://github.com/alibaba/arthas
- 阿爾薩斯官方文檔
- 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 運作成功的界面
指令 top 定位到的異常的 HBase 程序 ID 是 1214,該程序就是 HRegionServer 的程序。輸入序号 1,回車,就進入了監聽該程序的指令行界面。
4.3 dashboard
運作 dashboard 指令回車,就可以檢視該程序占用資源的總體情況,可以從圖中看到,ID 為 59 的線程,占用的 CPU 最高。
4.4 thread
輸入 thread 指令回車,檢視該程序下所有線程的執行情況。
4.5 thread -n 3
輸出資源占用前三名的線程。
4.6 thread -n 3 -i 5000
機關時間為 5 秒内,資源占用前三名的線程。
4.7 使用async-profiler生成火焰圖
生成火焰圖的最簡單指令。
profiler start
隔一段時間,大概三十秒。
profiler stop
在 web console 裡檢視。
關于火焰圖的入門級知識:
檢視 jvm 程序 cpu 火焰圖工具。
火焰圖裡很清楚地定位到 CPU 時間占用最高的線程是綠框最長的那些線程,也就是 scan 操作。
5. scan 操作引起的 CPU 負載過高
通過以上的程序分析,我們最終可以确定,scan 操作的發生,導緻 CPU 負載很高。我們查詢 HBase 的 API 基于 happybase 封裝而成,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='x0fx10&Rxcaxdfx96xcbxe2xad7$xad9khEx19xfdxaax87xa5xddxf7x85x1cx81ku ^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='x0fx10&Rxcaxdfx96xcbxe2xad7$xad9khEx19xfdxaax87xa5xddxf7x85x1cx81ku ^x92k',
limit=3))
except Exception as e:
pass
end = time.time()
print 'timeout: %d' % (end - start)
程式開始運作時,可以打開 arthas 進入到 HRegionServer 程序的監控,運作 thread 指令,檢視此時的線程使用情況:
小部分在運作,大部分在等待。此時,CPU 的負載情況:
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='x0fx10&Rxcaxdfx96xcbxe2xad7$xad9khEx19xfdxaax87xa5xddxf7x85x1cx81ku ^x92k',
limit=3))
except Exception as e:
pass
end = time.time()
print 'timeout: %d' % (end - start)
下圖中可以看到開始 RUNNING 的線程越來越多,CPU 的消耗也越來越大。
此時 CPU 的使用情況,由剛才的較為平穩,陡然上升:
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='x0fx10&Rxcaxdfx96xcbxe2xad7$xad9khEx19xfdxaax87xa5xddxf7x85x1cx81ku ^x92k',
limit=3))
except Exception as e:
pass
end = time.time()
print 'timeout: %d' % (end - start)
如果不指定逾時時間,會隻有一個線程持續運作,因為我的連接配接池設定為 1。
CPU 的負載也不是太高,如果我的連接配接池設定的更大,或者我的并發加大,那麼這些耗時 scan 的線程應該會更多,CPU 使用率也會飙升。
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='x0fx10&Rxcaxdfx96xcbxe2xad7$xad9khEx19xfdxaax87xa5xddxf7x85x1cx81ku ^x92k',
limit=3))
except Exception as e:
pass
end = time.time()
print 'timeout: %d' % (end - start)
此次測試中,我指定了連接配接池中的逾時時間,期望的是,連接配接逾時,及時斷開,繼續下一次耗時查詢。此時,服務端處理 scan 請求的線程情況:
服務端用于處理 scan 請求的 RUNNING 狀态的線程持續增長,并耗費大量的 CPU。
7. hbase.regionserver.handler.count
參考大神的部落格,以及自己對這個參數的了解,每一個用戶端發起的 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
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 有關的内容
歡迎參加征文活動,還有獎品拿哦~點選投稿
“阿裡巴巴雲原生關注微服務、Serverless、容器、Service Mesh 等技術領域、聚焦雲原生流行技術趨勢、雲原生大規模的落地實踐,做最懂雲原生開發者的公衆号。”