程式員，請你不要在坑程式員了🤣

>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，一個二線城市的程式員