大家好,我们最近业务量暴涨,导致我最近一直 TM 人傻了。前几天晚上,发现由于业务压力激增,某个核心微服务新扩容起来的几个实例,在不同程度上,出现了 Redis 连接失败的异常:
org.springframework.data.redis.RedisConnectionFailureException: Unable to connect to Redis; nested exception is io.lettuce.core.RedisConnectionException: Unable to connect to redis.production.com at org.springframework.data.redis.connection.lettuce.LettuceConnectionFactory$ExceptionTranslatingConnectionProvider.translateException(LettuceConnectionFactory.java:1553) ~[spring-data-redis-2.4.9.jar!/:2.4.9] at org.springframework.data.redis.connection.lettuce.LettuceConnectionFactory$ExceptionTranslatingConnectionProvider.getConnection(LettuceConnectionFactory.java:1461) ~[spring-data-redis-2.4.9.jar!/:2.4.9] at org.springframework.data.redis.connection.lettuce.LettuceConnection.doGetAsyncDedicatedConnection(LettuceConnection.java:1027) ~[spring-data-redis-2.4.9.jar!/:2.4.9] at org.springframework.data.redis.connection.lettuce.LettuceConnection.getOrCreateDedicatedConnection(LettuceConnection.java:1013) ~[spring-data-redis-2.4.9.jar!/:2.4.9] at org.springframework.data.redis.connection.lettuce.LettuceConnection.openPipeline(LettuceConnection.java:527) ~[spring-data-redis-2.4.9.jar!/:2.4.9] at org.springframework.data.redis.connection.DefaultStringRedisConnection.openPipeline(DefaultStringRedisConnection.java:3245) ~[spring-data-redis-2.4.9.jar!/:2.4.9] at jdk.internal.reflect.GeneratedMethodAccessor319.invoke(Unknown Source) ~[?:?] at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?] at java.lang.reflect.Method.invoke(Method.java:566) ~[?:?] at org.springframework.data.redis.core.CloseSuppressingInvocationHandler.invoke(CloseSuppressingInvocationHandler.java:61) ~[spring-data-redis-2.4.9.jar!/:2.4.9] at com.sun.proxy.$Proxy355.openPipeline(Unknown Source) ~[?:?] at org.springframework.data.redis.core.RedisTemplate.lambda$executePipelined$1(RedisTemplate.java:318) ~[spring-data-redis-2.4.9.jar!/:2.4.9] at org.springframework.data.redis.core.RedisTemplate.execute(RedisTemplate.java:222) ~[spring-data-redis-2.4.9.jar!/:2.4.9] at org.springframework.data.redis.core.RedisTemplate.execute(RedisTemplate.java:189) ~[spring-data-redis-2.4.9.jar!/:2.4.9] at org.springframework.data.redis.core.RedisTemplate.execute(RedisTemplate.java:176) ~[spring-data-redis-2.4.9.jar!/:2.4.9] at org.springframework.data.redis.core.RedisTemplate.executePipelined(RedisTemplate.java:317) ~[spring-data-redis-2.4.9.jar!/:2.4.9] at org.springframework.data.redis.core.RedisTemplate.executePipelined(RedisTemplate.java:307) ~[spring-data-redis-2.4.9.jar!/:2.4.9] at org.springframework.data.redis.core.RedisTemplate$$FastClassBySpringCGLIB$$81812bd6.invoke(<generated>) ~[spring-data-redis-2.4.9.jar!/:2.4.9] //省略一些堆栈 Caused by: org.springframework.dao.QueryTimeoutException: Redis command timed out at org.springframework.data.redis.connection.lettuce.LettuceConnection.closePipeline(LettuceConnection.java:592) ~[spring-data-redis-2.4.9.jar!/:2.4.9] ... 142 more
同时,也有业务调用 Redis 命令超时的异常:
org.springframework.data.redis.connection.RedisPipelineException: Pipeline contained one or more invalid commands; nested exception is org.springframework.data.redis.connection.RedisPipelineException: Pipeline contained one or more invalid commands; nested exception is org.springframework.dao.QueryTimeoutException: Redis command timed out at org.springframework.data.redis.connection.lettuce.LettuceConnection.closePipeline(LettuceConnection.java:594) ~[spring-data-redis-2.4.9.jar!/:2.4.9] at org.springframework.data.redis.connection.DefaultStringRedisConnection.closePipeline(DefaultStringRedisConnection.java:3224) ~[spring-data-redis-2.4.9.jar!/:2.4.9] at jdk.internal.reflect.GeneratedMethodAccessor198.invoke(Unknown Source) ~[?:?] at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?] at java.lang.reflect.Method.invoke(Method.java:566) ~[?:?] at org.springframework.data.redis.core.CloseSuppressingInvocationHandler.invoke(CloseSuppressingInvocationHandler.java:61) ~[spring-data-redis-2.4.9.jar!/:2.4.9] at com.sun.proxy.$Proxy355.closePipeline(Unknown Source) ~[?:?] at org.springframework.data.redis.core.RedisTemplate.lambda$executePipelined$1(RedisTemplate.java:326) ~[spring-data-redis-2.4.9.jar!/:2.4.9] at org.springframework.data.redis.core.RedisTemplate.execute(RedisTemplate.java:222) ~[spring-data-redis-2.4.9.jar!/:2.4.9] at org.springframework.data.redis.core.RedisTemplate.execute(RedisTemplate.java:189) ~[spring-data-redis-2.4.9.jar!/:2.4.9] at org.springframework.data.redis.core.RedisTemplate.execute(RedisTemplate.java:176) ~[spring-data-redis-2.4.9.jar!/:2.4.9] at org.springframework.data.redis.core.RedisTemplate.executePipelined(RedisTemplate.java:317) ~[spring-data-redis-2.4.9.jar!/:2.4.9] at org.springframework.data.redis.core.RedisTemplate.executePipelined(RedisTemplate.java:307) ~[spring-data-redis-2.4.9.jar!/:2.4.9] at org.springframework.data.redis.core.RedisTemplate$$FastClassBySpringCGLIB$$81812bd6.invoke(<generated>) ~[spring-data-redis-2.4.9.jar!/:2.4.9] at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:218) ~[spring-core-5.3.7.jar!/:5.3.7] at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:779) ~[spring-aop-5.3.7.jar!/:5.3.7] at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163) ~[spring-aop-5.3.7.jar!/:5.3.7] at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:750) ~[spring-aop-5.3.7.jar!/:5.3.7] at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:97) ~[spring-aop-5.3.7.jar!/:5.3.7] at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186) ~[spring-aop-5.3.7.jar!/:5.3.7] at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:750) ~[spring-aop-5.3.7.jar!/:5.3.7] at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:692) ~[spring-aop-5.3.7.jar!/:5.3.7] at org.springframework.data.redis.core.StringRedisTemplate$$EnhancerBySpringCGLIB$$c9b8cc15.executePipelined(<generated>) ~[spring-data-redis-2.4.9.jar!/:2.4.9] //省略一部分堆栈 Caused by: org.springframework.data.redis.connection.RedisPipelineException: Pipeline contained one or more invalid commands; nested exception is org.springframework.dao.QueryTimeoutException: Redis command timed out at org.springframework.data.redis.connection.lettuce.LettuceConnection.closePipeline(LettuceConnection.java:592) ~[spring-data-redis-2.4.9.jar!/:2.4.9] ... 142 more Caused by: org.springframework.dao.QueryTimeoutException: Redis command timed out at org.springframework.data.redis.connection.lettuce.LettuceConnection.closePipeline(LettuceConnection.java:592) ~[spring-data-redis-2.4.9.jar!/:2.4.9] ... 142 more
我们的 spring-data-redis 的配置是:
spring: redis: host: redis.production.com port: 6379 # 命令超时 timeout: 3000 lettuce: pool: max-active: 128 max-idle: 128 max-wait: 3000
这些请求虽然在第一次请求发送到的实例失败了,但是我们有重试的机制,请求最后还是成功了。但是比正常的请求多了 3s,这部分请求占了所有请求的 3% 左右。
从异常堆栈上面可以看出,异常的根源都是 redis 命令超时,但是为何建立 Redis 连接的时候,也会有 Redis 命令执行呢?
我们的 Redis 访问,使用的是 spring-data-redis + Lettuce 连接池。默认情况下,Lettuce 中的 Redis 连接建立的流程是:
针对 Redis 2.x ~ 5.x 的版本,我们可以配置是否在启用连接前发送 PING 心跳,默认为是:
ClientOptions
public static final boolean DEFAULT_PING_BEFORE_ACTIVATE_CONNECTION = true;
我们使用的 Redis 版本是最新的 6.x,所以在建立连接,握手的阶段,一定需要发送一个 HELLO 命令,并等待响应成功才算连接创建成功。
那么为何这个简单的命令也会超时呢?
我们的项目中 redis 操作是通过 spring-data-redis + Lettuce 连接池,启用并且增加了关于 Lettuce 命令的 JFR 监控,可以参考我的这篇文章:这个 Redis 连接池的新监控方式针不戳~我再加一点佐料,截至目前我的 pull request 已经合并,这个特性会在 6.2.x 版本发布。我们看下出问题时间附近的 Redis 命令采集,如下图所示:
可以看出,这时候 Redis 压力还是比较大的(图中的 firstResponsePercentiles 的单位是微秒)。我们这个时候,有 7 个实例,这个实例时刚启动的,压力相对于其他实例还比较小,就已经出现了连接命令超时。而且我们这里只截取了 HGET 命令,还有 GET 命令执行的次数和 HGET 是同一量级的,然后剩下其他的命令加起来相当于 HGET 的一半。这时候从客户端看,发往 Redis 的命令的 QPS 已经超过了百万。
从 Redis 的监控来看,压力确实有一些,可能会造成某些命令等待过长时间导致超时异常。
我们先明确一点,针对 spring-data-redis + lettuce,如果我们没有使用需要独占连接的命令(包括 Redis 事务以及 Redis Pipeline),那么我们不需要连接池,因为 lettuce 是异步响应式的,对于可以使用共享连接的请求,都会使用同一个实际的 redis 连接进行请求,不需要连接池。但是这个微服务中,使用了大量的 pipeline 命令来提高查询效率。如果我们不使用连接池,那么会导致频繁的连接关闭与创建(每秒几十万个),这样会严重降低效率。虽然官网说,lettuce 不需要连接池,但是这是在你没有使用事务以及 Pipeline 的情况下。
首先,Redis 扩容:我们的 Redis 部署在公有云上,如果扩容也就是提高机器配置,下一个更高的配置指标相对于当前多了一倍,成本也是高了差不多一倍。目前只有在瞬时压力的时候,会出现少于 3% 的请求失败并重试下一实例,最后还是成功,针对这个对 Redis 进行扩容,从成本考虑并不值得。
然后,对于压力过大的应用,我们是有动态扩容机制存在的。对于失败的请求,我们也是有重试的。但是这个问题给我们带来的影响是:
其实,如果我们有办法尽量减少或者避免连接创建失败,那么就能很大程度优化这个问题。即在微服务实例开始提供服务前,就将连接池中所有的连接创建好。
我们首先看看,是否可以借助于官方配置,实现这个连接池。
我们查看官方文档,发现了这样两个配置:
min-idle 即连接池中最少的连接数。 time-between-eviction-runs 是定时任务,检查连接池中的连接是否满足至少有 min-idle 的个数,同时,不超过 max-idle 那么多个数。官方文档中说,min-idle 只有配合 time-between-eviction-runs 都配置,才会生效。究其原因是:lettuce 的链接池是基于 commons-pool 实现的。连接池可以配置 min-idle,但是需要手动调用 preparePool,才会创建至少 min-idle 个数的对象:
GenericObjectPool
public void preparePool() throws Exception { //如果配置了有效的 min-idle,则调用 ensureMinIdle 保证创建至少 min-idle 个数的对象 if (this.getMinIdle() >= 1) { this.ensureMinIdle(); } }
那么这个是在什么时候调用呢? commons-pool 有定时任务,初始延迟和定时间隔都是 time-between-eviction-runs,配置的,其内容是:
public void run() { final ClassLoader savedClassLoader = Thread.currentThread().getContextClassLoader(); try { if (factoryClassLoader != null) { // Set the class loader for the factory final ClassLoader cl = factoryClassLoader.get(); if (cl == null) { // The pool has been dereferenced and the class loader // GC'd. Cancel this timer so the pool can be GC'd as // well. cancel(); return; } Thread.currentThread().setContextClassLoader(cl); } // Evict from the pool try { evict(); } catch(final Exception e) { swallowException(e); } catch(final OutOfMemoryError oome) { // Log problem but give evictor thread a chance to continue // in case error is recoverable oome.printStackTrace(System.err); } // Re-create idle instances. try { ensureMinIdle(); } catch (final Exception e) { swallowException(e); } } finally { // Restore the previous CCL Thread.currentThread().setContextClassLoader(savedClassLoader); } }
可以看出,这个定时任务执行主要保证当前池内空闲对象个数不超过 max-idle,同时至少有 min-idle 个链接。这些都是 common-pools 自己带的机制。但是没有我们需要的,在连接池一创建就去初始化所有链接。
这就需要我们自己实现了,我们首先配置 min-idle = max-idle = max-active,这样无论何时连接池中都有同样最大个数的链接。之后,我们在连接池创建出来的地方,修改源码,强制调用 preparePool 去初始化所有链接,即:
ConnectionPoolSupport
// lettuce 初始化创建连接池的时候,会调用这个方法 public static <T extends StatefulConnection<?, ?>> GenericObjectPool<T> createGenericObjectPool( Supplier<T> connectionSupplier, GenericObjectPoolConfig<T> config, boolean wrapConnections) { //省略其他代码 GenericObjectPool<T> pool = new GenericObjectPool<T>(new RedisPooledObjectFactory<T>(connectionSupplier), config) { @Override public T borrowObject() throws Exception { return wrapConnections ? ConnectionWrapping.wrapConnection(super.borrowObject(), poolRef.get()) : super.borrowObject(); } @Override public void returnObject(T obj) { if (wrapConnections && obj instanceof HasTargetConnection) { super.returnObject((T) ((HasTargetConnection) obj).getTargetConnection()); return; } super.returnObject(obj); } }; //创建好后,调用 preparePool try { pool.preparePool(); } catch (Exception e) { throw new RedisConnectionException("prepare connection pool failed",e); } //省略其他代码 }
这样,我们就可以实现初始化 Redis 的时候,在微服务真正提供服务之前,初始化所有 Redis 链接。由于这里涉及源码修改,大家目前可以通过在项目中添加同名同路径的类,进行依赖库源码替换。针对这个优化,我也向 lettuce 提了 issue 以及对应的 pull request:
微信搜索“我的编程喵”关注公众号,每日一刷,轻松提升技术,斩获各种offer: