一次redis连接配置修改引发的redis.clients.jedis.exceptions.JedisConnectionException: Unexpected end of stream.异常

  在一次修改了redis配置之后,出现了大批量的redis.clients.jedis.exceptions.JedisConnectionException: Unexpected end of stream.
  原配置
 1 JedisPoolConfig jedisPoolConfig = new JedisPoolConfig();
 2 jedisPoolConfig.setMaxTotal(150);
 3 jedisPoolConfig.setMaxIdle(30);
 4 jedisPoolConfig.setMinIdle(10);
 5 jedisPoolConfig.setNumTestsPerEvictionRun(1024);
 6 jedisPoolConfig.setTimeBetweenEvictionRunsMillis(30000);
 7 jedisPoolConfig.setMinEvictableIdleTimeMillis(1800000);
 8 jedisPoolConfig.setSoftMinEvictableIdleTimeMillis(1800000);
 9 jedisPoolConfig.setMaxWaitMillis(1500);
10 jedisPoolConfig.setTestOnBorrow(true);
11 jedisPoolConfig.setTestWhileIdle(true);
12 jedisPoolConfig.setBlockWhenExhausted(false);
  修改后的配置
 1 JedisPoolConfig jedisPoolConfig = new JedisPoolConfig();
 2 jedisPoolConfig.setMaxTotal(60);
 3 jedisPoolConfig.setMaxIdle(60);
 4 jedisPoolConfig.setMinIdle(60);
 5 jedisPoolConfig.setNumTestsPerEvictionRun(1024);
 6 jedisPoolConfig.setTimeBetweenEvictionRunsMillis(30000);
 7 jedisPoolConfig.setMinEvictableIdleTimeMillis(1800000);
 8 jedisPoolConfig.setSoftMinEvictableIdleTimeMillis(1800000);
 9 jedisPoolConfig.setMaxWaitMillis(500);
10 jedisPoolConfig.setTestOnBorrow(false);
11 jedisPoolConfig.setTestWhileIdle(true);
12 jedisPoolConfig.setBlockWhenExhausted(false);
  如果一开始你就看出异常出现的问题所在了,那么这篇文章你就不用看了,是在浪费你的时间
 
  而我看到这个异常最开始的想法是redis-server出现了问题,在不停debug的时候猜测是redis-server掐断了jedis连接,导致数据没有传输完成就断开了连接,但是这个想法怎么都没办法说服自己,虽然后来还是一直往这个方向方向查,因为福尔摩斯说过,排开所有不可能,剩下的那个原因再不可能那也是真相。可是福尔摩斯没有说怎么去找到最后的那个不可能,作为菜鸟的我一开始就把那个真相的不可能给排出了。对,我一开始就跑偏了,凤梨和菠萝傻傻分不清。
 
  这几天有点空闲时间,所以想着吧jedis的源码都好好看一遍,看一下我对这个配置的修改到底引发了jedis的怎么不满,让它那么想弄死我。
一开始查找的方向是testOnBorrow和testWhileIdle,因为我的理解来看,其它几个修改应该不会引发redis-server对我的不满。不会那么随意掐断我的jedis连接。
testOnBorrow有原来的true改为了false,即在每次查询获取链接的时候,都会检查一下获取到的这个链接是否有效,也即是在borrow一个jedis链接之前,会用这个链接向redis-server发送一个PING命令,如果能得到一个PONG响应则返回此链接给调用者,而我为了节约这一次请求,所以就吧testOnBorrow改成了false。因为testWhileIdle改为了true,所以理所当然的认为在空闲的时候会触发pool中失效的连接的释放。
 
  所以从现在开始,去彻底理解修改了的这两个参数的工作流,首先去阅读testOnBorrow参数源码如下:
 
org.apache.commons.pool2.impl.GenericObjectPool<T>
 1 if (p != null && (getTestOnBorrow() || create && getTestOnCreate())) {
 2     boolean validate = false;
 3     Throwable validationThrowable = null;
 4     try {
 5         validate = factory.validateObject(p);
 6     } catch (final Throwable t) {
 7         PoolUtils.checkRethrow(t);
 8         validationThrowable = t;
 9     }
10     if (!validate) {
11         try {
12             destroy(p);
13             destroyedByBorrowValidationCount.incrementAndGet();
14         } catch (final Exception e) {
15             // Ignore - validation failure is more important
16         }
17         p = null;
18         if (create) {
19             final NoSuchElementException nsee = new NoSuchElementException(
20                     "Unable to validate object");
21             nsee.initCause(validationThrowable);
22             throw nsee;
23         }
24     }
25 }
 
  在第5行调用了factory.validateObject(p),这一行代码的作用则是保证获取到的实例是安全的,对于jedis来说,就是保证获取到的连接是可用的,而且验证方法实现,则是利用获取到的jedis连接想redis-server发送了一个PING命令,判断是否能得到一个PONG响应,是则连接可用,反之则不可用。源码如下:
redis.clients.jedis.JedisFactory
 1 @Override
 2 public boolean validateObject(PooledObject<Jedis> pooledJedis) {
 3   final BinaryJedis jedis = pooledJedis.getObject();
 4   try {
 5     HostAndPort hostAndPort = this.hostAndPort.get();
 6     String connectionHost = jedis.getClient().getHost();
 7     int connectionPort = jedis.getClient().getPort();
 8     return hostAndPort.getHost().equals(connectionHost)
 9         && hostAndPort.getPort() == connectionPort && jedis.isConnected()
10         && jedis.ping().equals("PONG");
11   } catch (final Exception e) {
12     return false;
13   }
14 }
  在修改testOnBorrow为false之后,每次获取jedis连接时就不会再进行以上的连接验证了。从这样的源码看来,对于testOnBorrow参数的理解好像也没有什么问题。
 
  而此时脑子里突然迸处一个想法,也许redis-server并没有对我有什么不满,也许出现的异常并不是在数据传输过程中,连接被掐断,而是连接一开始就断了。因为borrow一个连接的时候,没有对连接做有效性检查,那么可能borrow获取到的连接本身就是无效的,而testWhileIdle,可能根本就没有空闲的时候。为此,有去看testWhileIdle的工作流程。最后还是在org.apache.commons.pool2.impl.GenericObjectPool<T>的public abstract void evict() throws Exception;实现中找到了关于testWhileIdle的调用。
 1 // User provided eviction policy could throw all sorts of
 2 // crazy exceptions. Protect against such an exception
 3 // killing the eviction thread.
 4 boolean evict;
 5 try {
 6     evict = evictionPolicy.evict(evictionConfig, underTest,
 7             idleObjects.size());
 8 } catch (final Throwable t) {
 9     // Slightly convoluted as SwallowedExceptionListener
10     // uses Exception rather than Throwable
11     PoolUtils.checkRethrow(t);
12     swallowException(new Exception(t));
13     // Don't evict on error conditions
14     evict = false;
15 }
16 if (evict) {
17     destroy(underTest);
18     destroyedByEvictorCount.incrementAndGet();
19 } else {
20     if (testWhileIdle) {
21         boolean active = false;
22         try {
23             factory.activateObject(underTest);
24             active = true;
25         } catch (final Exception e) {
26             destroy(underTest);
27             destroyedByEvictorCount.incrementAndGet();
28         }
29         if (active) {
30             if (!factory.validateObject(underTest)) {
31                 destroy(underTest);
32                 destroyedByEvictorCount.incrementAndGet();
33             } else {
34                 try {
35                     factory.passivateObject(underTest);
36                 } catch (final Exception e) {
37                     destroy(underTest);
38                     destroyedByEvictorCount.incrementAndGet();
39                 }
40             }
41         }
42     }
43     if (!underTest.endEvictionTest(idleObjects)) {
44         // TODO - May need to add code here once additional
45         // states are used
46     }
47 }
  这是一个空闲线程移除的方法,Jedis中默认的触发频率是30s(我的配置也是30s),但timeBetweenEvictionRunsMillis和minEvictableIdleTimeMillis配置的时间都是1800s,所以,空闲超过半个小时的连接才会被回收,没有超过半小时的连接会走20行的逻辑,而在testWhileIdle为true时,虽然有destroy无效连接的时候,但是在debug时却从来没有看到被调用过,在第30行的连接校验也是通过校验了的。也就是说连接池中的连接始终有效,直到配置的MinEvictableIdleTimeMillis和SoftMinEvictableIdleTimeMillis的条件(半个小时)触发第6行使得evict为true的时候,批量destroy旧的连接,然后新建新的连接重新放入pool中。
 
  到现在为止,猜测有两点,一、borrow从pool中拿到的连接就是无效的;二、testWhileIdle空闲检查时,所有的连接都有效。这是一个矛盾的结论,所以让我先想想静静。
后来想了一下,服务器会断开空闲客户端,更何况我已经把redis-server的连接数占满了。问了一下运维的同学,说的是服务的会主动断开超过5s的空闲连接,后来想了一下,因为服务实例比较多,每个实例60的连接,很容易超过redis允许的最大连接数,而实际上应用可能用不到60个连接,使用旧的连接配置时,每个容器的连接数也就在10个,就是最小空闲连接数,所以使用新配置时,最小空闲连接数时60,也就是说每个容器至少有50个连接都是浪费的,所以在pool中可能会存在大量的连接没使用到,导致大量的连接被redis-server主动断开,导致实例中会存在很多失效的连接,虽然每隔30s会进行一次清理,但是redis-server断开的频率可能更高(因为连接满了不够用),导致Jedis获取到的连接大概率无效。
当然最后的猜测我没有实验成功,主要是环境一直没有弄好,如果以后弄好了,我在补上。
posted @ 2019-04-24 13:33  深海囚徒  阅读(...)  评论(...编辑  收藏