線上服務CPU使用率百分百，註冊中心卻看不到該服務

• 2020 年 2 月 24 日
• 筆記

轉自：Java藝術

線上某服務一直運行很穩定，最近突然就cpu百分百，rpc遠程調用全部失敗，並走了mock邏輯。重啟後，一個小時後問題又重現。於是dump執行緒棧資訊，但不仔細看也看不出什麼問題。於是就有了一番排查歷程。

前一天，我dump執行緒棧資訊後發現佔用cpu高的執行緒是阿里的限流組件sentinel，並根據執行緒棧資訊知道，在sentinel控制台會拉取該服務的qps統計資訊。這個介面會讀取本地文件內容，因為qps資訊是輸出到/root/logs/csp/目錄下的某個文件的，並且是用NIO方式讀取文件。因此我猜測是sentinel在某種條件下會觸發死循環bug，也就能解釋得清楚為什麼cpu會出現百分百的使用率。

帶著這個猜測，我調試了一遍源碼，也並未復現。於是我將限流功能暫時去掉，以為問題就能解決，但是沒想到第二天早上又看到這個問題。於是我先將該服務的其它節點重啟，留下一個節點，並將剩下的節點從註冊中心中剔除。可沒想到的是，註冊中心已經沒有這個節點了，應該是所有該服務的節點都與註冊中心失聯了，其它是因為重啟之後重新註冊到註冊中心的。

既然沒有註冊到註冊中心，其它服務調用直接走mock邏輯也解釋得通。繼續前一天的進度，我首先是查看文件句柄數是否打開很多，於是使用lsof查看，果然不出所料。

進程15567打開的文件句柄數20多萬，因此我更願意相信是sentinel讀取文件出現bug的猜測，因為我想起前一天限流功能還沒有完全去除，只是去除了限流配置。接著查看這個進程是否打開了/root/logs/csp目錄下的文件（這個目錄是從限流組件的源碼中找出來的）。

遺憾的是看不到每個文件的打開數量。接著我用lsof -p 進程id命令查看下，該進程打開的文件句柄資訊。

於是我發現打開最多的不是/root/logs/csp目錄下的文件，而是redis連接。這下只能將限流組件sentinel有bug的猜測去掉了，因為昨天去掉配置後，也並沒有看到sentinel執行緒佔用cpu過高的現象了，只能排除。繼續統計redis的socket打開數量。

確實對上了，文件句柄數達上限的問題確實是與redis-cluster有關。於是我使用redis-cli命令連接上redis服務，看下是否連接數增多了，是否與該進程持有的文件句柄數對得上。因為前一天我也發現某消息消費服務偶爾出現連接超時的情況。

然而並未發現什麼異常，客戶端連接數與平常一樣。只能懸於此了。於是我又去分析執行緒棧資訊，發現大量的dubbo執行緒處於wait狀態，且都是阻塞在歸還redis連接到連接池以及從連接池中申請連接這一步。

還有少數幾個dubbo執行緒當前是runing狀態，原因是這些執行緒走了記憶體快取。程式碼中我是用aop實現記憶體快取的，命中記憶體快取的不會往下走業務邏輯，也就不會用到redis。因此這些執行緒處理的請求是正常的。

那麼為什麼cpu會百分百呢？大片的業務執行緒都已經被阻塞住了，都在wait狀態，到底是什麼執行緒佔用如此高的cpu。於是我才想到用top命令去查看。

看到兩個非業務相關的執行緒，佔用非常高的cpu，於是又回去琢磨執行緒棧資訊，與top命令顯示的command列對得上的也就只有兩個垃圾回收執行緒。

於是就是jstat命令查看gc垃圾回收情況。

連續使用jstat命令查看gc情況，發現每次執行命令，大概是1秒多，fgc的次數就加1了。問題的真相已經非常接近。找到這裡，接著就是排查業務程式碼。

由於使用了記憶體快取，會導致full gc的情況很正常。我首先想到兩點，一是快取數據太多，二是快取數據清理的定時任務執行失敗了。

由於之前該服務一直很穩定，猜測可能是數據格式不正確觸發的bug，導致數據清理失敗，越積越多。但是看了程式碼後，我是加了try-catch的，出異常也會移除快取，只是清理時間間隔比較長，一個小時才清理一次。那麼就是數據量暴增的原因。

到此，我就不再往下分析。去掉記憶體快取？那就需要加好幾台機器來扛下目前的並發數，而且還需要添加Redis節點，想想也是不可能的。所以只能計算業務所需要的記憶體，提升實例的記憶體。

通過資料庫查詢，估算需要快取的記錄數是四百多萬，本地寫了個測試用例，計算四百多萬記錄大概消耗700多m的記憶體，因此，只需要將機器的記憶體稍微提高一點就沒有問題了。除非數據量還會暴漲，這也是某個業務功能的實現導致的。

但是我想不通的是，redis連接文件句柄數為什麼會如此高呢，連接池也沒問題，是fgc影響了什麼嗎？STW也不至於導致redis socket文件句柄這麼多吧？非常詭異的現象，我還在琢磨到底什麼原因。