1. 程式人生 > >連線池你用對了嗎?一次Unexpected end of stream異常的排查

連線池你用對了嗎?一次Unexpected end of stream異常的排查

能收穫什麼?

  1. 更加了解TCP協議
  2. Redis與客戶端關閉連線的機制
  3. 基於Apache Common連線池的引數調優
  4. 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);

根據上面的配置我們可知:

  1. 每次最多檢測3個連線
  2. 每隔5分鐘檢測一次
  3. 最小空閒連線數為5
  4. 最大連線數為20
  5. 關閉獲取連線時檢查連線可用
  6. 開啟空閒連線檢測
  7. 最大連線空閒數為8(這邊沒有明確設定,是Pool的預設值)

帶著這些已知的情況,我們去詢問了DBA Redis的keepalive的設定。
DBA回覆我們說:5分鐘
至此我們知道了原因,那就是Pool的設定和Redis的配置不匹配引起的。
我們設定一個場景來推演:

  1. 併發10次使用Pool操作Redis
  2. 當操作完成後Pool中應該還有8個空閒連線(最大連線空閒數為8,所以這邊不是10)
  3. 當5分鐘過後再次進行併發10次的Redis操作
  4. 應該會出現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次揮手這麼簡單的內容