程式設計師，請你不要在坑程式設計師了?

tom發表於2021-05-26
程式設計師

>jsoncat：https://github.com/Snailclimb/jsoncat （仿 Spring Boot 但不同於 Spring Boot 的一個輕量級的 HTTP 框架）

大家好，hellohello-tom又來分享實戰經驗了。?

在一個風和日麗的下午，tom哥正在工位上打著瞌睡，突然QQ群運維同學@全部開發人員說線上綠線環境大面積開始癱瘓，zuul閘道器大量介面返回service unavailable，並且範圍已經開始波及到紅、藍線，運維同學說發生事故的機器他們已經重啟了，但是在一段短時間後還是會繼續阻塞，運維主管緊急把此次事故定義為I級，全員備戰，要求開發人員迅速解決問題。

專案經理拉上java組同學緊急開會，tom哥也不敢怠慢，拉上運維我們就一起開始進行事故分析，開啟zabbix監控管理介面，檢視各項伺服器監控

隨便檢視一臺閘道器，我的天這伺服器連線數跟雲霄飛車一樣忽上忽下的，這鐵定是出問題了，趕快進行鏈路追蹤，發現部分介面請求時間在20s，現在全線業務響應都極其的緩慢，運維同學報告說，通過這幾次重啟發現一個共性，就是每當redis網路頻寬達到850m時會逐漸造成生產環境延時卡慢，最終造成服務不可用狀態，初步定位可能是redis的問題，但redis的網路正常，CPU正常，slowlog也都在合理範圍內現在只能期望我們java組同學看能否看出一絲端倪，tom哥一個踉蹌，趕快挺直腰板，心想I級屬於一級事故型別了，搞不好會被扣工資的，tom哥趕快開啟跳板機，隨便登入一臺下游綠線伺服器，檢視java應用程式

jps -l

按照tom哥的習慣,列印出java程式的pid後首先會去觀察各項記憶體指標、新生代老年代GC情況等

jstat -gcutil 11984 1000 10


非常健康，沒有發生full gc，ygc也少的可憐，既然如此那就分析下是否有CPU高負載的情況

top -Hp 11984


執行緒資訊也非常正常，沒有某個執行緒CPU負載特別高的，接下來繼續分析列印java應用程式執行緒堆疊，首先看看是不是有產生死鎖的地方

jstack -m 11984


這個說明程式也沒有產生死鎖相關的問題，那接下來只能繼續列印java執行緒堆疊具體乾的事了。

jstack 11984


這時候發現一絲問題，執行緒堆疊中有大量的ClusterCommandExcutor與對應的TIMED_WAITING狀態

jstack 11984 | grep ClusterCommandExecutor | wc -l

追蹤堆疊源

終於發現大量的執行緒等待發起源頭是在redisUtil的mget方法上，馬上開始審查呼叫這塊程式碼的源頭，發現業務程式碼中主要業務有一個mapByUserIds，會傳入一個使用者集合，然後根據使用者集合一次性會從redis獲取使用者的快取資訊，到這裡感覺基本已經能確認問題了，由於最近公司使用者量增加，在某些業務場景，發現會一次mget出10000個的使用者資訊，在這樣大批量的資料操作肯定會造成redis擠壓了，由於我們操作redis使用了jedisPool，如果一個連線請求大量的key時，可能就會造成連線池得不到釋放，如果連線池內都被這樣要獲取大資料量的連線佔滿時，就可能會引起整個專案從redis獲取資料時全面阻塞，等到連線之後才能繼續操作redis，引起雪崩。

知道這個場景，那程式碼就好修改了，大概解決思路是這樣的，在mget之前會進行一個拆分操作，把大key拆小，分多次從伺服器請求回需要獲取的使用者資訊

//100是測試後最理想的值
int count = Double.valueOf(Math.ceil(keys.size() / (double) 100)).intValue();
for (int i = 0; i < count; i++) {
      dataList.addAll(valueOperations.multiGet(keys.stream().skip(i * 100).limit(100).collect(Collectors.toList())));
}

就這麼隨意的解決了，但是感覺還是不太完美，如果1萬個使用者資訊的key，那我是單執行緒執行可能就要執行100次，這樣子也太慢了，加個併發處理吧

private ExecutorService executorService =  new ThreadPoolExecutor(4, 4,
        0L, TimeUnit.MILLISECONDS,
        new LinkedBlockingQueue<>(), new NamedThreadFactory("mget-redis-pool"));
        

int count = Double.valueOf(Math.ceil(keys.size() / (double) 100)).intValue();
List<future<list<string>&gt;&gt; future = new ArrayList&lt;&gt;();
for (int i = 0; i &lt; count; i++) {
    List<string> limitKeys = keys.stream().skip(i * 100).limit(100).collect(Collectors.toList());
    future.add(executorService.submit(() -&gt; dataList.addAll(valueOperations.multiGet(limitKeys))));
}
try {
    for (Future<list<string>&gt; f : future) {
        //這裡要考慮dataList執行緒併發安全哦
        dataList.addAll(f.get());
    }
} catch (Exception exception) {
    logger.error("mget彙總結果集錯誤,ex=", exception);
}

執行緒池的數量可以按照連線池中的連線數控制，保持在一個合理範圍設定一半就行，避免jedisPool內被打滿，感覺這樣子就已經完美解決問題，tom哥信心滿滿，提交測試，成功沒問題，發包上線，運維同學開始緊急補丁釋出。

就在tom哥以為這次問題就這樣完美的解決時，運維同學又在群裡發訊息了，不行啊剛發的包，不到10分鐘，又開始全面阻塞了，納尼，什麼情況，問題應該解決了呀，tom哥心中一驚，心想這不可能啊，急忙繼續登入問題伺服器排查問題

jstack 11984

這次mget的方法呼叫少了，但是redisUtils中各式各樣的方法報錯都出來了，有什麼不能從連線池內獲取連線的錯誤，有什麼當前節點不能獲取對應的redis key，要求讓MOVED等等，錯誤五花八門，這是怎麼回事呢,列印應用伺服器與redis伺服器連線情況

netstat -ano | grep 192.168.200.1


連線都處於建立成功狀態，聯絡運維同學發現此時redis各項指標也都正常，看來問題還是出在java應用上了，沒辦法只能列印堆疊了

jmap -dump:format=b,file=b.dump 11984

經過漫長的等待，下載好dump檔案使用Memory Analyzer進行記憶體物件分析，匯入開始進行分析


Netty類相關的可以忽略，但是

354 instances of "org.springframework.data.redis.connection.RedisClusterNode", loaded by "org.apache.catalina.loader.ParallelWebappClassLoader @ 0x501d75708" occupy 92,792,376 (18.26%) bytes.
這是什麼鬼，spring redis 中的RedisClusterNode這個物件記憶體難道存在記憶體洩漏的可能麼？spring官方說，我可不背這個鍋，分析下RedisClusterNode的堆疊引用吧，看到底什麼東西在使用它

通過引用來看還是執行緒池中持有大量的物件，結合執行緒堆疊資訊來看確實阻塞是發生在redis連線過程中，而spring redis 只是個殼，難道問題出現在客戶端上麼，繼續追蹤發現spring redis預設使用的是jedis客戶端連線，jedis客戶端版本2.9.0，google一把 jedis記憶體洩漏，滑一下子各式各樣的錯誤資訊提示出來了，官方也報了這個BUG，原來在高併發場景式，在釋放連線時由於上一個連線沒有來得及標記空，會導致連線池沒有即時歸還，從而導致連線洩漏。

#Bug1911

KAO，這樣太坑了，官方說在2.10.2以上版本中修復了此問題，jedis這個玩意兒你同步IO低效率還有這樣BUG，坑死程式設計師啊。不說了趕快換元件，升級一波jedis後測試沒有問題上線，tom哥心想這下問題可算能解決了吧，可以休息一會了，這時候已經深夜了。在等待短暫發包之後，tom哥還是聽到不幸的訊息，運維同學說還是有問題，tom哥頭疼的厲害，專案經理讓大家先回去休息了，先靠著線上運維同學手動不停的切換先度過去。

第二天一大早tom哥就來到公司，當再次登入到java應用程式伺服器時還是有和redis相關的大量TIMED_WAITING執行緒，tom哥已經開始懷疑阻塞是不是到底沒有產生在redis呢，聯絡運維同學開始抓包吧，不行就從http、tcp都抓出來看看，具體分析下這期間到底卡在哪一步了，

//因為會跳網路卡，所以我們需要捕獲所有網路卡的連線
tcpdump -i any -w allDump.cap

抓個2、3分鐘就可以了，主要看慢查詢相關的內容，下載到本地後匯入wireShark,分析一個慢查詢介面

進棧出棧將近7秒，這個查詢肯定不正常了，然後開始具體分析這期間到底都幹了什麼。

在wireshark中輸入過濾tcp，檢視版本號35512-46536中相關的內容，在一個一個排查tcp狀態的同時，終於發現有不正常的tcp

發現36830（應用服務埠）與7001(redis伺服器埠) 產生大量的tcp包的傳輸，並且是redis伺服器對應用伺服器發起的PSH ACK行為，，按照length進行排序，問題暴漏出來，在短短的3分鐘抓包記憶體在大量的報文傳輸，趕快去找源頭


在上面的tcp請求的抓包中終於看到應用伺服器去向redis獲取了一個key，後續的返回包都是根據這個Get key命令進行的響應，趕快去redis查一下這到底是個什麼玩意兒，執行get sys:app_device

我的天足足3.26s，把這個文字儲存到本地2.3m，看來問題找到了，就是這個redis大key的問題，聯絡專案經理，原來這個大key 存放的是封禁的app裝置號列表，現在資料已經達到10幾萬，並且java應用程式用的也有問題，把整個資料序列化成字串，塞到一個string value結構裡面，每次app在登入、註冊時都會呼叫此介面，造成redis阻塞，呼叫頻率非常頻繁，並且string到本地後在序列化成物件迴圈判斷當前app傳的裝置列表是否為凍結裝置，這簡直就是挖坑啊無語，難道你用hash不香麼，查詢複雜度也就O（1）而已。

緊急對這塊邏輯程式碼進行優化，設定快取優先資料庫滯後的處理方式，修改了業務程式碼，重新上線，至此在排查這個問題終於解決了


連線數終於不像老婆的心情，一天一個樣了，可算平穩了。這次問題真是前人挖坑導致的呀。

我是hellohello-tom，一個二線城市的程式設計師

相關文章