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

>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&lt;&gt;(), 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）而已。

緊急對這塊邏輯代碼進行優化，設置緩存優先數據庫滯后的處理方式，修改了業務代碼，重新上線，至此在排查這個問題終於解決了

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