大量redis.clients.jedis.exceptions.JedisConnectionException: java.net.SocketTimeoutException: Read timed out

问题描述：
1.生产部署情况：codis proxy: 2个节点，客户端用的jodis(开启了testOnReturn发送一个ping，超时时间2s)，redis3个（aof always）
2. 查看redis慢查询：没有， 但是有一个ping命令耗时2.5秒（这个不是关键，貌似只有一次），目前流量很小，fsync和rewrite冲突不会这么频繁，排除redis阻塞问题
3. codis proxy,日志太少，然后又是go语言，我没法排除，只能看到fails比较多
有一个规律就是：每次Read timed out的前2s都有一批jodis客户端quit:

proxy日志：
2019/04/16 22:59:13 session.go:87: [INFO] session [0xc435ffb080] closed: {"ops":4,"create":1555426751,"lastop":1555426753,"remote":"10.xx.xx.17:47156"}, quit
2019/04/16 22:59:13 session.go:87: [INFO] session [0xc420290f80] closed: {"ops":4,"create":1555426751,"lastop":1555426753,"remote":"10.xx.xx.17:47158"}, quit
2019/04/16 22:59:13 session.go:87: [INFO] session [0xc435ffb100] closed: {"ops":4,"create":1555426751,"lastop":1555426753,"remote":"10.xx.xx.17:47160"}, quit
2019/04/16 22:59:13 session.go:87: [INFO] session [0xc420290f00] closed: {"ops":8,"create":1555426751,"lastop":1555426753,"remote":"10.xx.xx.17:47154"}, quit
2019/04/16 22:59:13 session.go:87: [INFO] session [0xc42016b900] closed: {"ops":4,"create":1555426751,"lastop":1555426753,"remote":"10.xx.xx.17:47162"}, quit
2019/04/16 22:59:14 session.go:87: [INFO] session [0xc435ffa200] closed: {"ops":9,"create":1555426749,"lastop":1555426754,"remote":"10.xx.xx.14:52797"}, quit
2019/04/16 22:59:14 session.go:87: [INFO] session [0xc435ffb180] closed: {"ops":9,"create":1555426751,"lastop":1555426754,"remote":"10.xx.xx.17:47164"}, quit
2019/04/16 22:59:15 session.go:87: [INFO] session [0xc420291280] closed: {"ops":6,"create":1555426753,"lastop":1555426755,"remote":"10.xx.xx.14:52803"}, quit
2019/04/16 22:59:15 session.go:87: [INFO] session [0xc435ffb200] closed: {"ops":7,"create":1555426753,"lastop":1555426755,"remote":"10.xx.xx.14:52806"}, quit
2019/04/16 22:59:15 session.go:87: [INFO] session [0xc420291300] closed: {"ops":3,"create":1555426753,"lastop":1555426755,"remote":"10.xx.xx.14:52808"}, quit
2019/04/16 22:59:15 session.go:87: [INFO] session [0xc435ffb280] closed: {"ops":3,"create":1555426753,"lastop":1555426755,"remote":"10.xx.xx.14:52810"}, quit
2019/04/16 22:59:15 session.go:78: [INFO] session [0xc435ffb300] create: {"ops":0,"create":1555426755,"remote":"10.xx.xx.14:52829"}
2019/04/16 22:59:15 session.go:78: [INFO] session [0xc436355000] create: {"ops":0,"create":1555426755,"remote":"10.xx.xx.14:52830"}
2019/04/16 22:59:15 session.go:78: [INFO] session [0xc44100c400] create: {"ops":0,"create":1555426755,"remote":"10.xx.xx.14:52833"}
2019/04/16 22:59:15 session.go:78: [INFO] session [0xc420291480] create: {"ops":0,"create":1555426755,"remote":"10.xx.xx.14:52834"}
2019/04/16 22:59:15 session.go:78: [INFO] session [0xc420291500] create: {"ops":0,"create":1555426755,"remote":"10.xx.xx.14:52836"}
2019/04/16 22:59:15 session.go:78: [INFO] session [0xc420291580] create: {"ops":0,"create":1555426755,"remote":"10.xx.xx.14:52838"}
2019/04/16 22:59:15 session.go:78: [INFO] session [0xc435ffb380] create: {"ops":0,"create":1555426755,"remote":"10.xx.xx.14:52839"}
2019/04/16 22:59:15 session.go:78: [INFO] session [0xc420291600] create: {"ops":0,"create":1555426755,"remote":"10.xx.xx.17:47217"}
2019/04/16 22:59:15 session.go:78: [INFO] session [0xc420291680] create: {"ops":0,"create":1555426755,"remote":"10.xx.xx.17:47216"}
2019/04/16 22:59:15 session.go:78: [INFO] session [0xc436355080] create: {"ops":0,"create":1555426755,"remote":"10.xx.xx.17:47219"}
2019/04/16 22:59:15 session.go:78: [INFO] session [0xc420291700] create: {"ops":0,"create":1555426755,"remote":"10.xx.xx.17:47222"}
2019/04/16 22:59:15 session.go:78: [INFO] session [0xc436355100] create: {"ops":0,"create":1555426755,"remote":"10.xx.xx.17:47224"}
2019/04/16 22:59:15 session.go:78: [INFO] session [0xc435ffb400] create: {"ops":0,"create":1555426755,"remote":"10.xx.xx.17:47227"}
2019/04/16 22:59:15 session.go:78: [INFO] session [0xc44100c480] create: {"ops":0,"create":1555426755,"remote":"10.xx.xx.17:47228"}
2019/04/16 22:59:15 session.go:78: [INFO] session [0xc435ffb480] create: {"ops":0,"create":1555426755,"remote":"10.xx.xx.17:47229"}
2019/04/16 22:59:15 session.go:78: [INFO] session [0xc44100c500] create: {"ops":0,"create":1555426755,"remote":"10.xx.xx.14:52842"}
2019/04/16 22:59:15 session.go:78: [INFO] session [0xc436355180] create: {"ops":0,"create":1555426755,"remote":"10.xx.xx.17:47232"}
2019/04/16 22:59:19 session.go:78: [INFO] session [0xc435ffb500] create: {"ops":0,"create":1555426759,"remote":"10.xx.xx.14:52850"}
2019/04/16 22:59:40 session.go:78: [INFO] session [0xc42016af00] create: {"ops":0,"create":1555426780,"remote":"10.xx.xx.17:47341"}
2019/04/16 23:00:09 session.go:78: [INFO] session [0xc430aa7600] create: {"ops":0,"create":1555426809,"remote":"10.xx.xx.18:52619"}
2019/04/16 23:00:12 session.go:78: [INFO] session [0xc430aa7880] create: {"ops":0,"create":1555426812,"remote":"10.xx.xx.14:53680"}
2019/04/16 23:00:12 session.go:78: [INFO] session [0xc430aa7900] create: {"ops":0,"create":1555426812,"remote":"10.xx.xx.14:53682"}

Inizia con session.go di codis proxy intorno alle righe 78 e 87, quindi segui il timeout di jodis e la sequenza quit/create mostrata nei log. Confronta il comportamento del proxy con gli indizi relativi alle query lente di Redis e con il timeout client di due secondi. Il lavoro è completato quando la causa di Read timed out è stata riprodotta o isolata e sono stati identificati una correzione concreta o un test di regressione.

Scritto dal modello di indicizzazione a partire dal testo della issue.