連接池你用對了嗎?一次Unexpected end of stream異常的排查
- 2019 年 10 月 3 日
- 筆記
能收穫什麼？
- 更加了解TCP協議
- Redis與客戶端關閉連接的機制
- 基於Apache Common連接池的參數調優
- Linux網路抓包
情況簡介
近期遷移了部分應用到K8s中，業務開發人員回饋說，會發現頻繁出現 : redis.clients.jedis.exceptions.JedisConnectionException: Unexpected end of stream.
堆棧如下圖：
發生這個問題的應用的環境如下：
- Java8
- Jedis 2.9.0
排查
由於開發人員說近期才出現這個情況，我們首先懷疑是不是K8s環境的問題，進行了一輪K8s的網路環境問題排查。
我們首先利用tcpdump在node節點和容器內進行抓包。
tcpdump -i <interfaceName> -C 100 -s0 -n -w node.pcap tcp不出意外我們確實發現了大量由Redis伺服器響應給客戶端的RST（TCP Reset）包，連接重置。
至此我們還是懷疑是網路不穩定引起的。
我們搜索了TCP RST相關內容，可以看到RST一般由下列的幾個情況引起：
- 到不存在的埠的連接請求
- 異常終止一個連接
- 檢測半打開連接
極客的Redis，不按規矩出牌的"RST"？
隨後我們又對網路又進行了幾輪的測試。
突然覺得有點不對勁，我們點開了RST包之前的包查看了包的內容。
結果發現大部分是客戶端發起quit數據，Redis服務端返回ok RST。
雖然包的狀態是RST，但包內容確又是跟商量好的一樣是正常的"客戶端說退出，服務端說ok"。
帶著這個問題，我們查了下Redis的相關文檔，確實在默認情況下Redis是這麼約束的，quit之後返回一個RST包。
按照常理當連接不需要在使用的時候應該關閉連接，這種情況不是應該是我們理解的"TCP的4次揮手"來進行這個連接的告別（關閉）儀式嗎？
為什麼Redis的連接關閉使用"RST"？
我的猜想是 不進行繁雜的4次揮手來提升性能。
這麼做的好處是避免了4次揮手。
在網路情況差，客戶端不穩定等情況下，能極大減少time_wait、close_wait等問題。
Redis利用了TCP機制重新約束了客戶端和服務端來進行連接關閉，流程如下。
- 客戶端發送 "quit"
- 服務端返回 "ok" + RST
- 服務端直接強制關閉連接
- 客戶端收到 "ok" 後自己關閉這個連接，並自己保證後續不在使用這個連接進行通訊
既然返回"RST"是正常的，那麼是哪裡出了問題呢？
我們根據堆棧拋出的時間具體查看對應的RST包後發現，這種RST的情況與上面的不一致，這一次客戶端發送的並不是 "quit" 數據，而Redis確返回了 RST。
這時我覺得是Jedis這邊的問題，去看了Jedis的release notes和issue，發現並沒有相關的BUG。
我們重新看一下TCP流的記錄，發現這一次交互間隔了9分鐘，最後一次交互為04:10:59秒的keepalive包，而發生問題的包的時間為04:19:57，我們又把返回RST可能的原因放在了"檢測半打開連接"這點上。
我又一次查看了業務使用的場景，發現了JedisPool按如下情況設置：
config.setNumTestsPerEvictionRun(3); config.setTimeBetweenEvictionRunsMillis(Duration.ofMinutes(5).toMillis()); config.setMinIdle(5); config.setMaxTotal(20); config.setTestOnBorrow(false); config.setTestWhileIdle(true);根據上面的配置我們可知：
- 每次最多檢測3個連接
- 每隔5分鐘檢測一次
- 最小空閑連接數為5
- 最大連接數為20
- 關閉獲取連接時檢查連接可用
- 開啟空閑連接檢測
- 最大連接空閑數為8（這邊沒有明確設置，是Pool的默認值）
帶著這些已知的情況，我們去詢問了DBA Redis的keepalive的設置。
DBA回復我們說：5分鐘
至此我們知道了原因，那就是Pool的設置和Redis的配置不匹配引起的。
我們設定一個場景來推演：
- 並發10次使用Pool操作Redis
- 當操作完成後Pool中應該還有8個空閑連接（最大連接空閑數為8，所以這邊不是10）
- 當5分鐘過後再次進行並發10次的Redis操作
- 應該會出現5次
Unexpected end of stream異常（5個新連接被建立，5箇舊連接拋出異常）
為什麼會出現5次異常？
因為根據Pool的設置，每5分鐘才會檢查池中的3個Redis連接是否正常，但當時池中有8個空閑的連接，也就是說還有5個連接在客戶端是未知狀態（8-3=5），這5個連接可能是可用的，也可能是不可用的，這取決於Redis的設置。
而當下Redis設置的也是5分鐘，也就是說這8個連接全是不可用的，Pool根據空閑檢查機制幫我們剔除了3個，那麼還有5個連接是會被直接使用的，那麼就會拋出5次異常。
重現問題以驗證推演
驗證程式碼如下：
JedisPoolConfig config = new JedisPoolConfig(); config.setNumTestsPerEvictionRun(3); config.setTimeBetweenEvictionRunsMillis(Duration.ofMinutes(5).toMillis()); config.setMinIdle(5); config.setMaxTotal(20); config.setTestOnBorrow(false); config.setTestWhileIdle(true); JedisPool pool = new JedisPool(config, "x.x.x.x", 6379, 5000, "123456", 0); List<Integer> connectionNumbers = Stream.of(0, 1, 2, 3, 4, 5, 6, 7, 8, 9).collect(Collectors.toList()); // 從池中獲取10個連接後並一起關閉 connectionNumbers.stream().map(i -> pool.getResource()).collect(Collectors.toList()) .forEach(Jedis::close); System.out.println(String.format("active: %d", pool.getNumActive())); System.out.println(String.format("idle: %d", pool.getNumIdle())); // 等待5分鐘 + 5秒鐘（避免剛好卡在5分鐘時間點） Thread.sleep(Duration.ofMinutes(5).toMillis() + 5000); System.out.println(LocalDateTime.now()); System.out.println(String.format("active: %d", pool.getNumActive())); System.out.println(String.format("idle: %d", pool.getNumIdle())); // 從Pool中取出10個連接，來進行redis操作 connectionNumbers.stream() .map(i -> pool.getResource()) .collect(Collectors.toList()) .forEach(resource -> { try { resource.get("key"); } catch (Exception e) { e.printStackTrace(); } });結果如下：
確實發生了5次 Unexpected end of stream 異常。
寫在最後
Jedis的連接池基於Apache Common中的連接池，大多數java中的連接池都是基於Apache。
所以該問題同樣適用於常見的JDBC連接池。
關於TCP
可以發現，TCP協議"一廂情願"總會出問題，更多時候得"你知我知"才能正常的使用。
TCP協議是真的很複雜的一個通訊協議，不單單是三次握手4次揮手這麼簡單的內容。
