記一次Jedis連接池泄漏的分析

1. 背景

隨著業(yè)務(wù)的快速發(fā)展屑迂,公司使用redis cluster+本地緩存的模式來化解大流量下對系統(tǒng)的沖擊跟狱。
redis客戶端驅(qū)動采用的是市面上流行的jedis,版本為2.6.2.

jedis采用連接池的方式來滿足多線程對redis的訪問需要朵夏。
在高并發(fā)以及大服務(wù)集群的環(huán)境下良价,jedis有各種弊端:

  1. 連接池的模式采用了傳統(tǒng)bio的通信模式,資源利用效率低下搏色,完全沒有發(fā)揮nio無阻塞雙工通信的優(yōu)勢
  2. 連接池的模式善茎,服務(wù)節(jié)點(diǎn)數(shù)目上去之后(尤其是大促期間擴(kuò)容),很可能超過redis的連接數(shù)限制
  3. jedis讓人莫名其妙的異常信息频轿,讓人很難定位到問題所在
  4. 不支持mget垂涯,mset以及pipeline等指令,但又支持了很多對業(yè)務(wù)沒太大用處的管理指令航邢。
  5. 在特定場景下會發(fā)生連接泄漏的問題耕赘,需要重啟業(yè)務(wù)服務(wù)才能恢復(fù)。

所以膳殷,目前架構(gòu)組在研發(fā)一個基于nio的redis驅(qū)動鞠苟,以取代jedis。

2. 故障描述

jedis的問題困擾了我們好久秽之,尤其是連接泄漏的問題当娱,直接影響到業(yè)務(wù)。

在研究了業(yè)務(wù)異常日志后考榨,發(fā)現(xiàn)有2個問題:

2.1 jedis連接池耗盡跨细,且一直無法恢復(fù)

理論上,在服務(wù)啟動后的瞬間河质, 大量請求涌進(jìn)來冀惭, 而這時候連接池還沒有準(zhǔn)備好連接, 這時候是可能存在短時間的連接耗盡掀鹅,從而導(dǎo)致服務(wù)拿不到連接的情況的散休。
但這種情況應(yīng)該在幾秒內(nèi)恢復(fù)正常。

如果一直都拿不到連接乐尊,那么毫無疑問戚丸,發(fā)生了連接池泄漏。
這時候扔嵌,日志上會大量打印:
Pool exhausted
或者:
Timeout waiting for idle object (如果配置了blockWhenExhausted的話)

使用Jmx工具或者arthas去查看連接池的狀態(tài)限府,發(fā)現(xiàn)就算沒有請求過來了夺颤, 其NumActive值依然保持在一個比較高的水平(如果沒請求過來的話,理論上大部分時間這個值都是0胁勺,除了恰好碰到j(luò)edis為維持連接而發(fā)送心跳包外)世澜。
更加印證了連接池泄漏真的發(fā)生了。

2.2 redis返回莫名其妙的MOVE指令

redis.clients.jedis.exceptions.JedisMovedDataException: MOVED 12790 172.30.221.82:14161

查了redis的手冊署穗,MOVED只有redis在發(fā)生槽遷移的時候寥裂,才有可能返回MOVED。 但發(fā)生異常的時候案疲,我們并沒有做任何槽的遷移操作封恰。

看了jedis的源碼,發(fā)現(xiàn)其邏輯為:

  1. 根據(jù)key拿到對應(yīng)redis節(jié)點(diǎn)的連接a(每個key可以算出落在哪個槽上, 從而算出具體的redis節(jié)點(diǎn),這里假設(shè)是redisA)
  2. 用連接a發(fā)送指令络拌,例如 get aaa
  3. 如果發(fā)生異常俭驮,例如拿不到連接、連接超時春贸、讀超時等混萝,會進(jìn)入重試階段(重試次數(shù)通過jedis參數(shù)配置), 隨機(jī)再拿一條連接b(對應(yīng)redisB),去發(fā)送同樣的指令
  4. 大部分情況下萍恕,redisB會返回MOVED xxx redisA (xxx為aaa所在的槽號逸嘀,告知客戶端aaa所在的槽xxx位于redisA中)

這個就是MOVED異常的由來了。
正常來說允粤,經(jīng)過MOVED后崭倘,后續(xù)jedis能再次拿到redisA的連接,從而得到正確的結(jié)果类垫。

詭異的是司光, 有時候key明明在redisA上,但是redis卻告訴你它在redisB上.
也就是說悉患, 用連接a發(fā)了一個指令get aaa残家, 結(jié)果redis返回MOVED xxx redisB

這就非常不可理解了。

3. 抓蟲經(jīng)歷

我們試圖把造成連接泄漏的線程揪出來售躁,于是修改了jedis的代碼坞淮,

  1. 當(dāng)某個線程申請到一個連接的時候,把線程的堆棧陪捷、連接信息以及申請時間記錄下來回窘,并記錄到集合a中。
  2. 當(dāng)線程歸還連接的時候市袖,把線程信息從集合a中去除啡直。

通過一個timer, 每隔5秒檢查一下,當(dāng)集合a中存在申請時間超過30秒的連接時付枫, 就認(rèn)為發(fā)生了泄漏烹玉,并把泄漏的連接對應(yīng)的線程堆棧打出來驰怎。

然后阐滩,在測試同事的鼎力幫忙下,把改造過的jedis放到壓測環(huán)境县忌,啟動tsung掂榔,開始了痛苦的抓蟲過程。

3.1 問題重現(xiàn)

開始并發(fā)量從2k增加到2w症杏,每輪持續(xù)5分鐘装获, 第一天、第二天都沒重現(xiàn)厉颤。
然后心一橫穴豫, 把接入層、服務(wù)分別擴(kuò)大到30臺逼友、40臺精肃,qps增大到20w, 還是很難重現(xiàn)問題帜乞。
恰好到周末了司抱, 把壓測時間放寬到10小時。 結(jié)果第二天早上一看黎烈,果然發(fā)生了連接池泄漏习柠。

現(xiàn)在回首,重現(xiàn)的前提是請求并發(fā)高照棋、redis壓力大且壓測的持續(xù)時間需要有一定的保證资溃,畢竟要重現(xiàn)的話,概率比較小烈炭。

看打印出來的線程堆棧溶锭,都是很正常的路徑,獲取連接一般都是在第一次訪問redis發(fā)生了讀超時或者獲取連接超后梳庆,重試的時候拿到的暖途。

那我們聚焦重試的時候拿連接的邏輯:

public Jedis getConnection() {
  // In antirez's redis-rb-cluster implementation,
  // getRandomConnection always return valid connection (able to
  // ping-pong)
  // or exception if all connections are invalid

  List<JedisPool> pools = getShuffledNodesPool();

  for (JedisPool pool : pools) {
    Jedis jedis = null;
    try {
      jedis = pool.getResource();

      if (jedis == null) {
        continue;
      }

      String result = jedis.ping();

      if (result.equalsIgnoreCase("pong")) return jedis;

      pool.returnBrokenResource(jedis);
    } catch (JedisConnectionException ex) {
      if (jedis != null) {
        pool.returnBrokenResource(jedis);
      }
    }
  }

  throw new JedisConnectionException("no reachable node in cluster");
}

我們發(fā)現(xiàn),這里jedis只處理了連接異常并釋放了連接膏执。 有沒有可能存在其它異常驻售,導(dǎo)致連接沒有歸還呢?
于是我們在這里加了一個catch塊更米,捕獲所有的異常(Throwable).

3.2 柳暗花明

重新打包再出發(fā)欺栗, 又壓了一晚, 第二天,果不其然迟几,有個空指針在這一行報了出來:

String result = jedis.ping();

這個空指針會導(dǎo)致連接沒有歸還!

仔細(xì)看了代碼消请,各種路徑都不可能返回null。

一下子又沒了頭緒。

這時候扔水,@飛狐 又展現(xiàn)出了老司機(jī)風(fēng)范缔御, 建議通過tcpdump抓包,配合日志一起分析缸逃。

tcpdump抓包,這個鎮(zhèn)宅神奇厂抽,是最后一招了需频。

3.3 鎮(zhèn)宅神器 - tcpdump

又過了一晚,問題重現(xiàn)了筷凤, 并抓了服務(wù)節(jié)點(diǎn)跟redis之間的tcp通訊包昭殉。

3.3.1. 日志

日志1:

[2019-05-26 09:16:26:510]Jedis-Debugger:Thread:[Thread[DubboServerHandler-172.30.2.206:29955-thread-1629,5,main]], currentTs:1558833386510, detail:redirection:4, key:short_url_pre.qGZmAb, slot:137 java.net.SocketTimeoutException: Read timed out
[2019-05-26 09:16:26:510]Jedis-Debugger:Thread:[Thread[DubboServerHandler-172.30.2.206:29955-thread-1629,5,main]], currentTs:1558833386510, detail:redis.clients.jedis.exceptions.JedisConnectionException: java.net.SocketTimeoutException: Read timed out
        redis.clients.util.RedisInputStream.ensureFill(RedisInputStream.java:201)
        redis.clients.util.RedisInputStream.readByte(RedisInputStream.java:40)
        redis.clients.jedis.Protocol.process(Protocol.java:128)
        redis.clients.jedis.Protocol.read(Protocol.java:192)
        redis.clients.jedis.Connection.readProtocolWithCheckingBroken(Connection.java:287)
        redis.clients.jedis.Connection.getBinaryBulkReply(Connection.java:206)
        redis.clients.jedis.Connection.getBulkReply(Connection.java:195)
        redis.clients.jedis.Jedis.get$original$c4ny46N9(Jedis.java:93)
        redis.clients.jedis.Jedis.get$original$c4ny46N9$accessor$54NXOkqL(Jedis.java)
        redis.clients.jedis.Jedis$auxiliary$lC2USXlw.call(Unknown Source)
        com.yunji.erlang.agent.plugin.interceptor.enhance.InstMethodsInter.intercept(InstMethodsInter.java:87)
        redis.clients.jedis.Jedis.get(Jedis.java)
        yunji.stock.StockJedisCluster$3.execute(StockJedisCluster.java:358)
        yunji.stock.StockJedisCluster$3.execute(StockJedisCluster.java:355)
        redis.clients.jedis.JedisClusterCommand.runWithRetries(JedisClusterCommand.java:62)
        redis.clients.jedis.JedisClusterCommand.run(JedisClusterCommand.java:35)
        yunji.stock.StockJedisCluster.get(StockJedisCluster.java:360)
        com.yunji.shorturl.service.provider.base.ShortUrlBaseService.getByJedis(ShortUrlBaseService.java:140)
        com.yunji.shorturl.service.provider.base.ShortUrlBaseService.getSourceByJedis(ShortUrlBaseService.java:68)
        com.yunji.shorturl.service.provider.ShortUrlWriteServiceImpl.genShortUrl(ShortUrlWriteServiceImpl.java:538)
        com.yunji.shorturl.service.provider.ShortUrlWriteServiceImpl.createShortUrlAddRealmName(ShortUrlWriteServiceImpl.java:145)
        com.alibaba.dubbo.common.bytecode.Wrapper7.invokeMethod(Wrapper7.java)
        com.alibaba.dubbo.rpc.proxy.javassist.JavassistProxyFactory$1.doInvoke(JavassistProxyFactory.java:46)
[2019-05-26 09:16:26:510]Jedis-Debugger:Thread:[Thread[DubboServerHandler-172.30.2.206:29955-thread-1629,5,main]], currentTs:1558833386510, detail:host:172.30.232.59, port:14159


....
[2019-05-26 09:16:26:801]Jedis-Debugger:Thread:[Thread[DubboServerHandler-172.30.2.206:29955-thread-1629,5,main]], currentTs:1558833386801, detail:PossibleJedisLeak :null
[2019-05-26 09:16:26:801]Jedis-Debugger:Thread:[Thread[DubboServerHandler-172.30.2.206:29955-thread-1629,5,main]], currentTs:1558833386801, detail:java.lang.NullPointerException
        redis.clients.jedis.JedisSlotBasedConnectionHandler.getConnection(JedisSlotBasedConnectionHandler.java:36)
        redis.clients.jedis.JedisClusterCommand.runWithRetries(JedisClusterCommand.java:56)
        redis.clients.jedis.JedisClusterCommand.runWithRetries(JedisClusterCommand.java:87)
        redis.clients.jedis.JedisClusterCommand.run(JedisClusterCommand.java:35)
        yunji.stock.StockJedisCluster.get(StockJedisCluster.java:360)
        com.yunji.shorturl.service.provider.base.ShortUrlBaseService.getByJedis(ShortUrlBaseService.java:140)
        com.yunji.shorturl.service.provider.base.ShortUrlBaseService.getSourceByJedis(ShortUrlBaseService.java:68)
        com.yunji.shorturl.service.provider.ShortUrlWriteServiceImpl.genShortUrl(ShortUrlWriteServiceImpl.java:538)
        com.yunji.shorturl.service.provider.ShortUrlWriteServiceImpl.createShortUrlAddRealmName(ShortUrlWriteServiceImpl.java:145)

服務(wù)向redis發(fā)get請求后,讀超時藐守,然后隨機(jī)選擇了一個節(jié)點(diǎn)再次創(chuàng)建了一個連接挪丢,在返回連接前做了一個連接校驗(yàn)的動作

  1. 發(fā)PING請求給redis
  2. 預(yù)期redis返回PONG, 結(jié)果拿到的結(jié)果是null,
  3. 空指針從而導(dǎo)致連接泄漏
try {
  jedis = pool.getResource();

  if (jedis == null) {
    continue;
  }

  String result = jedis.ping();

  if (result.equalsIgnoreCase("pong")) return jedis;  //Line 36

  pool.returnBrokenResource(jedis);
} catch (JedisConnectionException ex) {
  if (jedis != null) {
    pool.returnBrokenResource(jedis);
  }
} catch (Throwable ex) {
  // TODO
  if (jedis != null) { // localPort, remoteIp,port
    Debugger.log("PossibleJedisLeak :" + ex.getMessage(), ex);
  }
}

注意這個時間點(diǎn)是09:16:26:801

接著吗伤,連接泄漏檢測線程檢測到有連接泄漏了吃靠,打印出如下日志:

[2019-05-26 09:16:59:354]Jedis-Debugger-simpleLog:!! PossibleJedisLeak: Jedis-Debugger-Error:ConnInfo[172.30.232.59:14159] borrowed by Thread[DubboServerHandler-172.30.2.206:29955-thread-1629,5,main] at:1558833386765
java.lang.RuntimeException: connDebugger
        redis.clients.util.Debugger.addConn(Debugger.java:28)
        redis.clients.jedis.JedisPool.getResource(JedisPool.java:95)
        redis.clients.jedis.JedisSlotBasedConnectionHandler.getConnection(JedisSlotBasedConnectionHandler.java:28)
        redis.clients.jedis.JedisClusterCommand.runWithRetries(JedisClusterCommand.java:56)
        redis.clients.jedis.JedisClusterCommand.runWithRetries(JedisClusterCommand.java:87)
        redis.clients.jedis.JedisClusterCommand.run(JedisClusterCommand.java:35)
        yunji.stock.StockJedisCluster.get(StockJedisCluster.java:360)
        com.yunji.shorturl.service.provider.base.ShortUrlBaseService.getByJedis(ShortUrlBaseService.java:140)
        com.yunji.shorturl.service.provider.base.ShortUrlBaseService.getSourceByJedis(ShortUrlBaseService.java:68)
        com.yunji.shorturl.service.provider.ShortUrlWriteServiceImpl.genShortUrl(ShortUrlWriteServiceImpl.java:538)
        com.yunji.shorturl.service.provider.ShortUrlWriteServiceImpl.createShortUrlAddRealmName(ShortUrlWriteServiceImpl.java:145)

注意這條連接是在1558833386765生成的, 也就是2019-05-26 09:16:26 765

3.3.2. tcpdump日志

我們關(guān)注下相關(guān)時間段內(nèi)的tcp數(shù)據(jù)包:

##get
2019-05-26 09:16:24.508718 IP (tos 0x0, ttl 64, id 41654, offset 0, flags [DF], proto TCP (6), length 92)
    172.30.2.206.40970 > 172.30.232.59.14159: Flags [P.], cksum 0x4395 (incorrect -> 0x0db1), seq 1:41, ack 1, win 229, options [nop,nop,TS val 400338731 ecr 3351988106], length 40
        0x0000:  4500 005c a2b6 4000 4006 549f ac1e 02ce  E..\..@.@.T.....
        0x0010:  ac1e e83b a00a 374f b932 0da0 84f0 b53d  ...;..7O.2.....=
        0x0020:  8018 00e5 4395 0000 0101 080a 17dc af2b  ....C..........+
        0x0030:  c7cb 478a 2a32 0d0a 2433 0d0a 4745 540d  ..G.*2..$3..GET.
        0x0040:  0a24 3230 0d0a 7368 6f72 745f 7572 6c5f  .$20..short_url_
        0x0050:  7072 652e 7147 5a6d 4162 0d0a            pre.qGZmAb..
2019-05-26 09:16:24.508825 IP (tos 0x0, ttl 64, id 62135, offset 0, flags [DF], proto TCP (6), length 52)
    172.30.232.59.14159 > 172.30.2.206.40970: Flags [.], cksum 0x83b3 (correct), seq 1, ack 41, win 227, options [nop,nop,TS val 3351988106 ecr 400338731], length 0
        0x0000:  4500 0034 f2b7 4000 4006 04c6 ac1e e83b  E..4..@.@......;
        0x0010:  ac1e 02ce 374f a00a 84f0 b53d b932 0dc8  ....7O.....=.2..
        0x0020:  8010 00e3 83b3 0000 0101 080a c7cb 478a  ..............G.
        0x0030:  17dc af2b
##2秒后超時足淆, 產(chǎn)生read timeout異常巢块, 并關(guān)閉連接。
2019-05-26 09:16:26.510990 IP (tos 0x0, ttl 64, id 41655, offset 0, flags [DF], proto TCP (6), length 66)
    172.30.2.206.40970 > 172.30.232.59.14159: Flags [P.], cksum 0x437b (incorrect -> 0x6b9c), seq 41:55, ack 1, win 229, options [nop,nop,TS val 400340733 ecr 3351988106], length 14
        0x0000:  4500 0042 a2b7 4000 4006 54b8 ac1e 02ce  E..B..@.@.T.....
        0x0010:  ac1e e83b a00a 374f b932 0dc8 84f0 b53d  ...;..7O.2.....=
        0x0020:  8018 00e5 437b 0000 0101 080a 17dc b6fd  ....C{..........
        0x0030:  c7cb 478a 2a31 0d0a 2434 0d0a 5155 4954  ..G.*1..$4..QUIT
        0x0040:  0d0a                                     ..
2019-05-26 09:16:26.511082 IP (tos 0x0, ttl 64, id 62136, offset 0, flags [DF], proto TCP (6), length 52)
    172.30.232.59.14159 > 172.30.2.206.40970: Flags [.], cksum 0x7401 (correct), seq 1, ack 55, win 227, options [nop,nop,TS val 3351990108 ecr 400340733], length 0
        0x0000:  4500 0034 f2b8 4000 4006 04c5 ac1e e83b  E..4..@.@......;
        0x0010:  ac1e 02ce 374f a00a 84f0 b53d b932 0dd6  ....7O.....=.2..
        0x0020:  8010 00e3 7401 0000 0101 080a c7cb 4f5c  ....t.........O\
        0x0030:  17dc b6fd
2019-05-26 09:16:26.761088 IP (tos 0x0, ttl 64, id 62137, offset 0, flags [DF], proto TCP (6), length 62)
    172.30.232.59.14159 > 172.30.2.206.40970: Flags [P.], cksum 0xb73a (correct), seq 1:11, ack 55, win 227, options [nop,nop,TS val 3351990358 ecr 400340733], length 10
        0x0000:  4500 003e f2b9 4000 4006 04ba ac1e e83b  E..>..@.@......;
        0x0010:  ac1e 02ce 374f a00a 84f0 b53d b932 0dd6  ....7O.....=.2..
        0x0020:  8018 00e3 b73a 0000 0101 080a c7cb 5056  .....:........PV
        0x0030:  17dc b6fd 242d 310d 0a2b 4f4b 0d0a       ....$-1..+OK..
2019-05-26 09:16:26.761107 IP (tos 0x0, ttl 64, id 41656, offset 0, flags [DF], proto TCP (6), length 52)
    172.30.2.206.40970 > 172.30.232.59.14159: Flags [.], cksum 0x436d (incorrect -> 0x7201), seq 55, ack 11, win 229, options [nop,nop,TS val 400340983 ecr 3351990358], length 0
        0x0000:  4500 0034 a2b8 4000 4006 54c5 ac1e 02ce  E..4..@.@.T.....
        0x0010:  ac1e e83b a00a 374f b932 0dd6 84f0 b547  ...;..7O.2.....G
        0x0020:  8010 00e5 436d 0000 0101 080a 17dc b7f7  ....Cm..........
        0x0030:  c7cb 5056                                ..PV
2019-05-26 09:16:26.761094 IP (tos 0x0, ttl 64, id 62138, offset 0, flags [DF], proto TCP (6), length 52)
    172.30.232.59.14159 > 172.30.2.206.40970: Flags [F.], cksum 0x72fc (correct), seq 11, ack 55, win 227, options [nop,nop,TS val 3351990358 ecr 400340733], length 0
        0x0000:  4500 0034 f2ba 4000 4006 04c3 ac1e e83b  E..4..@.@......;
        0x0010:  ac1e 02ce 374f a00a 84f0 b547 b932 0dd6  ....7O.....G.2..
        0x0020:  8011 00e3 72fc 0000 0101 080a c7cb 5056  ....r.........PV
        0x0030:  17dc b6fd                                ....
2019-05-26 09:16:26.761124 IP (tos 0x0, ttl 64, id 41657, offset 0, flags [DF], proto TCP (6), length 52)
    172.30.2.206.40970 > 172.30.232.59.14159: Flags [R.], cksum 0x436d (incorrect -> 0x41d0), seq 55, ack 12, win 229, options [nop,nop,TS val 0 ecr 3351990358], length 0
        0x0000:  4500 0034 a2b9 4000 4006 54c4 ac1e 02ce  E..4..@.@.T.....
        0x0010:  ac1e e83b a00a 374f b932 0dd6 84f0 b548  ...;..7O.2.....H
        0x0020:  8014 00e5 436d 0000 0101 080a 0000 0000  ....Cm..........
        0x0030:  c7cb 5056                                ..PV


##########################################
##get
2019-05-26 09:16:26.760545 IP (tos 0x0, ttl 64, id 16696, offset 0, flags [DF], proto TCP (6), length 92)
    172.30.2.206.58294 > 172.30.232.59.14159: Flags [P.], cksum 0x4395 (incorrect -> 0xc855), seq 152287:152327, ack 12032, win 229, options [nop,nop,TS val 400340983 ecr 3351990354], length 40
        0x0000:  4500 005c 4138 4000 4006 b61d ac1e 02ce  E..\A8@.@.......
        0x0010:  ac1e e83b e3b6 374f 67d5 5b16 7bd8 9365  ...;..7Og.[.{..e
        0x0020:  8018 00e5 4395 0000 0101 080a 17dc b7f7  ....C...........
        0x0030:  c7cb 5052 2a32 0d0a 2433 0d0a 4745 540d  ..PR*2..$3..GET.
        0x0040:  0a24 3230 0d0a 7368 6f72 745f 7572 6c5f  .$20..short_url_
        0x0050:  7072 652e 5056 6164 7a4e 0d0a            pre.PVadzN..


## ack
2019-05-26 09:16:26.760631 IP (tos 0x0, ttl 64, id 48437, offset 0, flags [DF], proto TCP (6), length 52)
    172.30.232.59.14159 > 172.30.2.206.58294: Flags [.], cksum 0x5d46 (correct), seq 12032, ack 152327, win 227, options [nop,nop,TS val 3351990358 ecr 400340983], length 0
        0x0000:  4500 0034 bd35 4000 4006 3a48 ac1e e83b  E..4.5@.@.:H...;
        0x0010:  ac1e 02ce 374f e3b6 7bd8 9365 67d5 5b3e  ....7O..{..eg.[>
        0x0020:  8010 00e3 5d46 0000 0101 080a c7cb 5056  ....]F........PV
        0x0030:  17dc b7f7


## PING??
2019-05-26 09:16:26.765741 IP (tos 0x0, ttl 64, id 16697, offset 0, flags [DF], proto TCP (6), length 66)
    172.30.2.206.58294 > 172.30.232.59.14159: Flags [P.], cksum 0x437b (incorrect -> 0x4915), seq 152327:152341, ack 12032, win 229, options [nop,nop,TS val 400340988 ecr 3351990358], length 14
        0x0000:  4500 0042 4139 4000 4006 b636 ac1e 02ce  E..BA9@.@..6....
        0x0010:  ac1e e83b e3b6 374f 67d5 5b3e 7bd8 9365  ...;..7Og.[>{..e
        0x0020:  8018 00e5 437b 0000 0101 080a 17dc b7fc  ....C{..........
        0x0030:  c7cb 5056 2a31 0d0a 2434 0d0a 5049 4e47  ..PV*1..$4..PING
        0x0040:  0d0a


## ack
2019-05-26 09:16:26.765828 IP (tos 0x0, ttl 64, id 48438, offset 0, flags [DF], proto TCP (6), length 52)
    172.30.232.59.14159 > 172.30.2.206.58294: Flags [.], cksum 0x5d2e (correct), seq 12032, ack 152341, win 227, options [nop,nop,TS val 3351990363 ecr 400340988], length 0
        0x0000:  4500 0034 bd36 4000 4006 3a47 ac1e e83b  E..4.6@.@.:G...;
        0x0010:  ac1e 02ce 374f e3b6 7bd8 9365 67d5 5b4c  ....7O..{..eg.[L
        0x0020:  8010 00e3 5d2e 0000 0101 080a c7cb 505b  ....].........P[
        0x0030:  17dc b7fc


## 兩個響應(yīng)巧号,一個是對上面get的響應(yīng) $-1, 另一個是PING的響應(yīng)PONG
2019-05-26 09:16:26.801028 IP (tos 0x0, ttl 64, id 48439, offset 0, flags [DF], proto TCP (6), length 64)
    172.30.232.59.14159 > 172.30.2.206.58294: Flags [P.], cksum 0x51f1 (correct), seq 12032:12044, ack 152341, win 227, options [nop,nop,TS val 3351990398 ecr 400340988], length 12
        0x0000:  4500 0040 bd37 4000 4006 3a3a ac1e e83b  E..@.7@.@.::...;
        0x0010:  ac1e 02ce 374f e3b6 7bd8 9365 67d5 5b4c  ....7O..{..eg.[L
        0x0020:  8018 00e3 51f1 0000 0101 080a c7cb 507e  ....Q.........P~
        0x0030:  17dc b7fc 242d 310d 0a2b 504f 4e47 0d0a  ....$-1..+PONG..




2019-05-26 09:17:06.867043 IP (tos 0x0, ttl 64, id 48440, offset 0, flags [DF], proto TCP (6), length 52)
    172.30.232.59.14159 > 172.30.2.206.58294: Flags [.], cksum 0xc032 (correct), seq 12043, ack 152341, win 227, options [nop,nop,TS val 3352030464 ecr 400341063], length 0
        0x0000:  4500 0034 bd38 4000 4006 3a45 ac1e e83b  E..4.8@.@.:E...;
        0x0010:  ac1e 02ce 374f e3b6 7bd8 9370 67d5 5b4c  ....7O..{..pg.[L
        0x0020:  8010 00e3 c032 0000 0101 080a c7cb ed00  .....2..........
        0x0030:  17dc b847                                ...G
2019-05-26 09:17:06.867053 IP (tos 0x0, ttl 64, id 16699, offset 0, flags [DF], proto TCP (6), length 52)
    172.30.2.206.58294 > 172.30.232.59.14159: Flags [.], cksum 0x436d (incorrect -> 0xc057), seq 152341, ack 12044, win 229, options [nop,nop,TS val 400381089 ecr 3351990398], length 0
        0x0000:  4500 0034 413b 4000 4006 b642 ac1e 02ce  E..4A;@.@..B....
        0x0010:  ac1e e83b e3b6 374f 67d5 5b4c 7bd8 9371  ...;..7Og.[L{..q
        0x0020:  8010 00e5 436d 0000 0101 080a 17dd 54a1  ....Cm........T.
        0x0030:  c7cb 507e                                ..P~


## FIN
2019-05-26 09:17:27.574951 IP (tos 0x0, ttl 64, id 48441, offset 0, flags [DF], proto TCP (6), length 52)
    172.30.232.59.14159 > 172.30.2.206.58294: Flags [F.], cksum 0xd2f2 (correct), seq 12044, ack 152341, win 227, options [nop,nop,TS val 3352051171 ecr 400381089], length 0
        0x0000:  4500 0034 bd39 4000 4006 3a44 ac1e e83b  E..4.9@.@.:D...;
        0x0010:  ac1e 02ce 374f e3b6 7bd8 9371 67d5 5b4c  ....7O..{..qg.[L
        0x0020:  8011 00e3 d2f2 0000 0101 080a c7cc 3de3  ..............=.
        0x0030:  17dd 54a1                                ..T.


## ACK
2019-05-26 09:17:27.614148 IP (tos 0x0, ttl 64, id 16700, offset 0, flags [DF], proto TCP (6), length 52)
    172.30.2.206.58294 > 172.30.232.59.14159: Flags [.], cksum 0x436d (incorrect -> 0x81e4), seq 152341, ack 12045, win 229, options [nop,nop,TS val 400401837 ecr 3352051171], length 0
        0x0000:  4500 0034 413c 4000 4006 b641 ac1e 02ce  E..4A<@.@..A....
        0x0010:  ac1e e83b e3b6 374f 67d5 5b4c 7bd8 9372  ...;..7Og.[L{..r
        0x0020:  8010 00e5 436d 0000 0101 080a 17dd a5ad  ....Cm..........
        0x0030:  c7cc 3de3

沒搞懂族奢, 客戶端(同一個線程)通過socket(172.30.2.206.58294 > 172.30.232.59.14159)跟redis發(fā)生關(guān)系,

  1. 首先發(fā)了一個get
  2. 然后發(fā)了一個PING(為何這時候會有PING丹鸿?)
  3. redis同時返回了上面兩個請求的響應(yīng) $-1+PONG越走,但這時候-1就產(chǎn)生了空指針。

這里沒搞明白為何在一個get請求之后會有個PING靠欢。

此外廊敌, 在看tcp包的時候, 經(jīng)常會發(fā)現(xiàn)一條連接接連發(fā)了多個指令給redis门怪,然后redis一次發(fā)回多個響應(yīng)的情況骡澈。
有些懷疑人生了,因?yàn)閖edis是用請求-響應(yīng)掷空,再請求-再響應(yīng)這種交互模式的(非pipeline下)肋殴。
莫非tcpdump發(fā)生了丟包囤锉,導(dǎo)致我們看到的是假象?

確實(shí)护锤, 從tcpdump的日志可以看出(tcpdump在退出的時候會打印一些統(tǒng)計(jì)數(shù)據(jù))官地, 有1.8w+的包給丟棄了。

4492851 packets captured
4675218 packets received by filter
182367 packets dropped by kernel

于是烙懦,調(diào)整了一下參數(shù)(主要是s0改為了s256驱入,詳見本文后的抓包腳本),繼續(xù)抓包。
果然修陡,丟包現(xiàn)象沒有了沧侥, 但是依然存在同一條連接給一個或者多個線程連發(fā)2個指令的情況可霎。

這時候已經(jīng)分析了差不多一個月了魄鸦, 身心俱疲, 且山窮水盡癣朗,就要放棄了拾因。

明知道存在泄漏, 但不知道為何會泄漏旷余。
明知道你在那里绢记, 但不知道你在哪里。

3.3. 問題根源

抱著最后一搏的心態(tài)整理了一下思路正卧,發(fā)現(xiàn)出現(xiàn)問題時蠢熄,往往伴隨著一次jedis的超時,這時候redis會一次返回兩個指令的結(jié)果炉旷, 從而導(dǎo)致上面兩個問題签孔。

但jedis是連接池的模式, 單個線程獨(dú)占一條連接窘行,發(fā)完一個指令饥追, 有了響應(yīng)之后才會發(fā)第二個請求。
出現(xiàn)上面的問題罐盔,只有一個解釋但绕,就是jedis出現(xiàn)異常的時候, 沒有關(guān)閉連接而是釋放了連接惶看。

看代碼捏顺, 果不其然,在超時后纬黎,會觸發(fā)JedisConnectionException幅骄, 然后如果是隨機(jī)模式,jedis會進(jìn)入finally塊釋放而不是關(guān)閉連接

private T runWithRetries(String key, int redirections, boolean tryRandomNode, boolean asking) {
    if (redirections <= 0) {
        throw new JedisClusterMaxRedirectionsException("Too many Cluster redirections?");
    }

    Jedis connection = null;
    try {

        if (asking) {
            //...
        } else {
            if (tryRandomNode) {
                connection = connectionHandler.getConnection();
            } else {
                connection = connectionHandler.getConnectionFromSlot(JedisClusterCRC16.getSlot(key));
            }
        }

        return execute(connection);
    } catch (JedisConnectionException jce) {
        if (tryRandomNode) {
            // maybe all connection is down
            throw jce;
        }

        releaseConnection(connection, true);
        connection = null;

        // retry with random connection
        return runWithRetries(key, redirections - 1, true, asking);
    } catch (JedisRedirectionException jre) {
        //....
    } finally {
        releaseConnection(connection, false);
    }

}

4. 問題重現(xiàn)條件

要重現(xiàn)上述問題的話莹桅,需要滿足如下條件:
問題1-連接泄漏:

  1. 線程a向redis1發(fā)一個請求昌执,超時烛亦,關(guān)閉連接,然后選擇隨機(jī)選擇一個節(jié)點(diǎn)懂拾, 恰好也選擇回redis1煤禽,
  2. a向redis1發(fā)請求,繼續(xù)超時岖赋,這時候由于是random模式檬果, 不會關(guān)閉連接而只是釋放連接
  3. 線程b拿到redis1這條連接,發(fā)PING
  4. redis1返回兩個響應(yīng)唐断,第一個是線程a的響應(yīng)选脊, 第二個是PONG。 如果第一個響應(yīng)是-1(表示key不存在)脸甘, 那么就會觸發(fā)空指針恳啥,導(dǎo)致連接溢出

問題2-無中生有的MOVED指令:

  1. 線程a向redis1發(fā)一個請求,get keyA, 超時丹诀,關(guān)閉鏈接钝的,隨機(jī)選擇一個節(jié)點(diǎn),為redis2
  2. 線程a向redis2發(fā)請求铆遭,get keyA, 超時硝桩,這時候由于是random模式, 不會關(guān)閉連接而只是釋放連接
  3. 線程b拿到redis2枚荣,發(fā)請求 get keyB
  4. redis2返回兩個響應(yīng)碗脊,一個是線程a的響應(yīng): move redis1, 第二個是線程b的響應(yīng)。
  5. 線程b會拿到move redis1這個響應(yīng)橄妆,然后就很疑惑衙伶, 明明keyB在redis2上, 為何要我move去redis1呼畸?

5. 問題解決

在異常情況下痕支,不管任何模式,都必須關(guān)閉連接蛮原,防止進(jìn)入不可知之地卧须。

@@ -58,17 +58,20 @@ public abstract class JedisClusterCommand<T> {
 
       return execute(connection);
     } catch (JedisConnectionException jce) {
+      releaseConnection(connection, true);
+      connection = null;
+
       if (tryRandomNode) {
         // maybe all connection is down
         throw jce;
       }
 
-      releaseConnection(connection, true);
-      connection = null;
-
       // retry with random connection
       return runWithRetries(key, redirections - 1, true, asking);
     } catch (JedisRedirectionException jre) {
+      releaseConnection(connection, false);
+      connection = null;
+
       if (jre instanceof JedisAskDataException) {
         asking = true;
         askConnection.set(this.connectionHandler.getConnectionFromNode(jre.getTargetNode()));
@@ -80,9 +83,6 @@ public abstract class JedisClusterCommand<T> {
         throw new JedisClusterException(jre);
       }
 
-      releaseConnection(connection, false);
-      connection = null;
-
       return runWithRetries(key, redirections - 1, false, asking);
     } finally {
       releaseConnection(connection, false);

另外, 也可以通過設(shè)置AbandonedConfig, 對長時間沒歸還的活躍連接進(jìn)行定期清理儒陨,一定程度上緩解連接泄漏造成的服務(wù)不可用的情況

6. 后記

jedis的最新版本已經(jīng)解決了這個問題花嘶。但升級也會存在風(fēng)險。
我們的版本是2.6.2蹦漠, jedis-2.7.x依然存在這個問題椭员, 而且,新的版本也引入了其它的bug笛园,在沒有踩過坑的情況下隘击,不建議貿(mào)然升級侍芝,何況我們即將推出重量級(實(shí)際上很輕巧)的自研Yedis驅(qū)動呢

抓包腳本

#!/bin/bash
nohup tcpdump -i eth0 -s 256 -C 1024 host 172.30.232.59 and tcp -n -X  -w redisTcpDump.cap &
最后編輯于
?著作權(quán)歸作者所有,轉(zhuǎn)載或內(nèi)容合作請聯(lián)系作者
  • 序言:七十年代末,一起剝皮案震驚了整個濱河市埋同,隨后出現(xiàn)的幾起案子州叠,更是在濱河造成了極大的恐慌,老刑警劉巖凶赁,帶你破解...
    沈念sama閱讀 222,464評論 6 517
  • 序言:濱河連續(xù)發(fā)生了三起死亡事件咧栗,死亡現(xiàn)場離奇詭異,居然都是意外死亡虱肄,警方通過查閱死者的電腦和手機(jī)致板,發(fā)現(xiàn)死者居然都...
    沈念sama閱讀 95,033評論 3 399
  • 文/潘曉璐 我一進(jìn)店門,熙熙樓的掌柜王于貴愁眉苦臉地迎上來咏窿,“玉大人斟或,你說我怎么就攤上這事『苍郑” “怎么了缕粹?”我有些...
    開封第一講書人閱讀 169,078評論 0 362
  • 文/不壞的土叔 我叫張陵,是天一觀的道長纸淮。 經(jīng)常有香客問我,道長亚享,這世上最難降的妖魔是什么咽块? 我笑而不...
    開封第一講書人閱讀 59,979評論 1 299
  • 正文 為了忘掉前任,我火速辦了婚禮欺税,結(jié)果婚禮上侈沪,老公的妹妹穿的比我還像新娘。我一直安慰自己晚凿,他們只是感情好亭罪,可當(dāng)我...
    茶點(diǎn)故事閱讀 69,001評論 6 398
  • 文/花漫 我一把揭開白布。 她就那樣靜靜地躺著歼秽,像睡著了一般应役。 火紅的嫁衣襯著肌膚如雪。 梳的紋絲不亂的頭發(fā)上燥筷,一...
    開封第一講書人閱讀 52,584評論 1 312
  • 那天箩祥,我揣著相機(jī)與錄音,去河邊找鬼肆氓。 笑死袍祖,一個胖子當(dāng)著我的面吹牛,可吹牛的內(nèi)容都是我干的谢揪。 我是一名探鬼主播蕉陋,決...
    沈念sama閱讀 41,085評論 3 422
  • 文/蒼蘭香墨 我猛地睜開眼捐凭,長吁一口氣:“原來是場噩夢啊……” “哼!你這毒婦竟也來了凳鬓?” 一聲冷哼從身側(cè)響起柑营,我...
    開封第一講書人閱讀 40,023評論 0 277
  • 序言:老撾萬榮一對情侶失蹤,失蹤者是張志新(化名)和其女友劉穎村视,沒想到半個月后官套,有當(dāng)?shù)厝嗽跇淞掷锇l(fā)現(xiàn)了一具尸體,經(jīng)...
    沈念sama閱讀 46,555評論 1 319
  • 正文 獨(dú)居荒郊野嶺守林人離奇死亡蚁孔,尸身上長有42處帶血的膿包…… 初始之章·張勛 以下內(nèi)容為張勛視角 年9月15日...
    茶點(diǎn)故事閱讀 38,626評論 3 342
  • 正文 我和宋清朗相戀三年奶赔,在試婚紗的時候發(fā)現(xiàn)自己被綠了。 大學(xué)時的朋友給我發(fā)了我未婚夫和他白月光在一起吃飯的照片杠氢。...
    茶點(diǎn)故事閱讀 40,769評論 1 353
  • 序言:一個原本活蹦亂跳的男人離奇死亡站刑,死狀恐怖,靈堂內(nèi)的尸體忽然破棺而出鼻百,到底是詐尸還是另有隱情绞旅,我是刑警寧澤,帶...
    沈念sama閱讀 36,439評論 5 351
  • 正文 年R本政府宣布温艇,位于F島的核電站因悲,受9級特大地震影響,放射性物質(zhì)發(fā)生泄漏勺爱。R本人自食惡果不足惜晃琳,卻給世界環(huán)境...
    茶點(diǎn)故事閱讀 42,115評論 3 335
  • 文/蒙蒙 一、第九天 我趴在偏房一處隱蔽的房頂上張望琐鲁。 院中可真熱鬧卫旱,春花似錦、人聲如沸围段。這莊子的主人今日做“春日...
    開封第一講書人閱讀 32,601評論 0 25
  • 文/蒼蘭香墨 我抬頭看了看天上的太陽奈泪。三九已至适贸,卻和暖如春,著一層夾襖步出監(jiān)牢的瞬間段磨,已是汗流浹背取逾。 一陣腳步聲響...
    開封第一講書人閱讀 33,702評論 1 274
  • 我被黑心中介騙來泰國打工, 沒想到剛下飛機(jī)就差點(diǎn)兒被人妖公主榨干…… 1. 我叫王不留苹支,地道東北人砾隅。 一個月前我還...
    沈念sama閱讀 49,191評論 3 378
  • 正文 我出身青樓,卻偏偏與公主長得像债蜜,于是被迫代替她去往敵國和親晴埂。 傳聞我的和親對象是個殘疾皇子究反,可洞房花燭夜當(dāng)晚...
    茶點(diǎn)故事閱讀 45,781評論 2 361

推薦閱讀更多精彩內(nèi)容

  • 包含的重點(diǎn)內(nèi)容:JAVA基礎(chǔ)JVM 知識開源框架知識操作系統(tǒng)多線程TCP 與 HTTP架構(gòu)設(shè)計(jì)與分布式算法數(shù)據(jù)庫知...
    消失er閱讀 4,333評論 1 10
  • 問題描述 其他業(yè)務(wù)線的同學(xué)在測試環(huán)境發(fā)現(xiàn)應(yīng)用程序一直不能獲取redis連接,我?guī)兔戳讼氯迓濉J紫瓤磻?yīng)用錯誤日志 問題...
    coder_jerry閱讀 54,001評論 1 57
  • NOSQL類型簡介鍵值對:會使用到一個哈希表精耐,表中有一個特定的鍵和一個指針指向特定的數(shù)據(jù),如redis琅锻,volde...
    MicoCube閱讀 4,000評論 2 27
  • 1.1 資料 卦停,最好的入門小冊子,可以先于一切文檔之前看恼蓬,免費(fèi)惊完。 作者Antirez的博客,Antirez維護(hù)的R...
    JefferyLcm閱讀 17,071評論 1 51
  • 在之前的文章中处硬,我們對redis批量處理指令mget進(jìn)行了壓測并分析了性能瓶頸小槐,顯然通過mget批量執(zhí)行指令可以節(jié)...
    近路閱讀 39,366評論 4 18