1. 背景
隨著業(yè)務的快速發(fā)展，公司使用redis cluster+本地緩存的模式來化解大流量下對系統(tǒng)的沖擊。
redis客戶端驅(qū)動采用的是市面上流行的jedis，版本為2.6.2.
jedis采用連接池的方式來滿足多線程對redis的訪問需要。
在高并發(fā)以及大服務集群的環(huán)境下，jedis有各種弊端：
- 連接池的模式采用了傳統(tǒng)bio的通信模式，資源利用效率低下，完全沒有發(fā)揮nio無阻塞雙工通信的優(yōu)勢
- 連接池的模式，服務節(jié)點數(shù)目上去之后(尤其是大促期間擴容)，很可能超過redis的連接數(shù)限制
- jedis讓人莫名其妙的異常信息，讓人很難定位到問題所在
- 不支持mget，mset以及pipeline等指令，但又支持了很多對業(yè)務沒太大用處的管理指令。
- 在特定場景下會發(fā)生連接泄漏的問題，需要重啟業(yè)務服務才能恢復。
所以，目前架構(gòu)組在研發(fā)一個基于nio的redis驅(qū)動，以取代jedis。
2. 故障描述
jedis的問題困擾了我們好久，尤其是連接泄漏的問題，直接影響到業(yè)務。
在研究了業(yè)務異常日志后，發(fā)現(xiàn)有2個問題:
2.1 jedis連接池耗盡，且一直無法恢復
理論上，在服務啟動后的瞬間， 大量請求涌進來， 而這時候連接池還沒有準備好連接， 這時候是可能存在短時間的連接耗盡，從而導致服務拿不到連接的情況的。
但這種情況應該在幾秒內(nèi)恢復正常。
如果一直都拿不到連接，那么毫無疑問，發(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)其邏輯為:
- 根據(jù)key拿到對應redis節(jié)點的連接a(每個key可以算出落在哪個槽上, 從而算出具體的redis節(jié)點,這里假設(shè)是redisA)
- 用連接a發(fā)送指令，例如 get aaa
- 如果發(fā)生異常，例如拿不到連接、連接超時、讀超時等，會進入重試階段(重試次數(shù)通過jedis參數(shù)配置), 隨機再拿一條連接b(對應redisB)，去發(fā)送同樣的指令
- 大部分情況下，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的代碼，
- 當某個線程申請到一個連接的時候，把線程的堆棧、連接信息以及申請時間記錄下來，并記錄到集合a中。
- 當線程歸還連接的時候，把線程信息從集合a中去除。
通過一個timer， 每隔5秒檢查一下，當集合a中存在申請時間超過30秒的連接時， 就認為發(fā)生了泄漏，并把泄漏的連接對應的線程堆棧打出來。
然后，在測試同事的鼎力幫忙下，把改造過的jedis放到壓測環(huán)境，啟動tsung，開始了痛苦的抓蟲過程。
3.1 問題重現(xiàn)
開始并發(fā)量從2k增加到2w，每輪持續(xù)5分鐘， 第一天、第二天都沒重現(xiàn)。
然后心一橫， 把接入層、服務分別擴大到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只處理了連接異常并釋放了連接。 有沒有可能存在其它異常，導致連接沒有歸還呢？
于是我們在這里加了一個catch塊，捕獲所有的異常(Throwable).
3.2 柳暗花明
重新打包再出發(fā)， 又壓了一晚， 第二天，果不其然，有個空指針在這一行報了出來:
String result = jedis.ping();
這個空指針會導致連接沒有歸還!
仔細看了代碼，各種路徑都不可能返回null。
一下子又沒了頭緒。
這時候，@飛狐 又展現(xiàn)出了老司機風范， 建議通過tcpdump抓包，配合日志一起分析。
tcpdump抓包，這個鎮(zhèn)宅神奇，是最后一招了。
3.3 鎮(zhèn)宅神器 - tcpdump
又過了一晚，問題重現(xiàn)了， 并抓了服務節(jié)點跟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)
服務向redis發(fā)get請求后，讀超時，然后隨機選擇了一個節(jié)點再次創(chuàng)建了一個連接，在返回連接前做了一個連接校驗的動作
- 發(fā)
PING請求給redis - 預期redis返回
PONG, 結(jié)果拿到的結(jié)果是null， - 空指針從而導致連接泄漏
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);
}
}
注意這個時間點是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
## 兩個響應，一個是對上面get的響應 $-1, 另一個是PING的響應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)系，
- 首先發(fā)了一個get
- 然后發(fā)了一個PING(為何這時候會有PING？）
- redis同時返回了上面兩個請求的響應 $-1+PONG，但這時候-1就產(chǎn)生了空指針。
這里沒搞明白為何在一個get請求之后會有個PING。
此外， 在看tcp包的時候， 經(jīng)常會發(fā)現(xiàn)一條連接接連發(fā)了多個指令給redis，然后redis一次發(fā)回多個響應的情況。
有些懷疑人生了，因為jedis是用請求-響應，再請求-再響應這種交互模式的(非pipeline下)。
莫非tcpdump發(fā)生了丟包，導致我們看到的是假象？
確實， 從tcpdump的日志可以看出(tcpdump在退出的時候會打印一些統(tǒng)計數(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é)果， 從而導致上面兩個問題。
但jedis是連接池的模式， 單個線程獨占一條連接，發(fā)完一個指令， 有了響應之后才會發(fā)第二個請求。
出現(xiàn)上面的問題，只有一個解釋，就是jedis出現(xiàn)異常的時候， 沒有關(guān)閉連接而是釋放了連接。
看代碼， 果不其然，在超時后，會觸發(fā)JedisConnectionException， 然后如果是隨機模式，jedis會進入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-連接泄漏:
- 線程a向redis1發(fā)一個請求，超時，關(guān)閉連接，然后選擇隨機選擇一個節(jié)點， 恰好也選擇回redis1，
- a向redis1發(fā)請求，繼續(xù)超時，這時候由于是random模式， 不會關(guān)閉連接而只是釋放連接
- 線程b拿到redis1這條連接，發(fā)PING
- redis1返回兩個響應，第一個是線程a的響應， 第二個是PONG。 如果第一個響應是-1(表示key不存在)， 那么就會觸發(fā)空指針，導致連接溢出
問題2-無中生有的MOVED指令:
- 線程a向redis1發(fā)一個請求，get keyA, 超時，關(guān)閉鏈接，隨機選擇一個節(jié)點，為redis2
- 線程a向redis2發(fā)請求，get keyA, 超時，這時候由于是random模式， 不會關(guān)閉連接而只是釋放連接
- 線程b拿到redis2，發(fā)請求 get keyB
- redis2返回兩個響應，一個是線程a的響應: move redis1, 第二個是線程b的響應。
- 線程b會拿到move redis1這個響應，然后就很疑惑， 明明keyB在redis2上， 為何要我move去redis1？
5. 問題解決
在異常情況下，不管任何模式，都必須關(guā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, 對長時間沒歸還的活躍連接進行定期清理，一定程度上緩解連接泄漏造成的服務不可用的情況
6. 后記
jedis的最新版本已經(jīng)解決了這個問題。但升級也會存在風險。
我們的版本是2.6.2， jedis-2.7.x依然存在這個問題， 而且，新的版本也引入了其它的bug，在沒有踩過坑的情況下，不建議貿(mào)然升級，何況我們即將推出重量級（實際上很輕巧）的自研Yedis驅(qū)動呢
抓包腳本
#!/bin/bash
nohup tcpdump -i eth0 -s 256 -C 1024 host 172.30.232.59 and tcp -n -X -w redisTcpDump.cap &
