大家好,我們最近業務量暴漲,導致我最近一直 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 命令執行呢?
lettuce 建立連接的流程
我們的 Redis 訪問,使用的是 spring-data-redis + Lettuce 連接池。默認情況下,Lettuce 中的 Redis 連接建立的流程是:
- 建立 TCP 連接
- 進行必要的握手:
- 針對 Redis 2.x ~ 5.x 的版本:
1. 如果需要用戶名密碼,則發送用戶名密碼信息
2. 如果開啟了連接使用前心跳,則發送 PING - 針對 Redis 6.x 的版本:6.x 之后引入了新命令 HELLO,使用這個命令來統一初始化 Redis 連接:REDIS HELLO,這個命令參數中可以帶用戶名與密碼,完成驗證。
針對 Redis 2.x ~ 5.x 的版本,我們可以配置是否在啟用連接前發送 PING 心跳,默認為是:
public static final boolean DEFAULT_PING_BEFORE_ACTIVATE_CONNECTION = true;
我們使用的 Redis 版本是最新的 6.x,所以在建立連接,握手的階段,一定需要發送一個 HELLO 命令,並等待響應成功才算連接創建成功。
那么為何這個簡單的命令也會超時呢?
通過 JFR 查看 Redis 命令壓力
我們的項目中 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 進行擴容,從成本考慮並不值得。
然后,對於壓力過大的應用,我們是有動態擴容機制存在的。對於失敗的請求,我們也是有重試的。但是這個問題給我們帶來的影響是:
- 由於瞬時壓力到來,新啟動的實例可能一開始就會有大量請求到來,導致接口請求和建立連接之后的心跳請求混合。並且由於這些請求並沒有公平隊列排序,某些心跳請求響應過慢從而導致失敗,重新建立連接依然可能失敗。
- 有些實例可能建立的連接比較少,不能滿足並發度需求。導致很多請求其實阻塞在等待連接的過程,從而使 CPU 壓力沒有一下子變很大,所以沒有繼續觸發擴容。這樣對於擴容帶來了更大的滯后性。
其實,如果我們有辦法盡量減少或者避免連接創建失敗,那么就能很大程度優化這個問題。即在微服務實例開始提供服務前,就將連接池中所有的連接創建好。
如何實現 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 個數的對象:
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 去初始化所有鏈接,即:
// 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:
- ConnectionPool would be better if prepared before used
- fix 1870,ConnectionPool would be better if prepared before used
微信搜索“我的編程喵”關注公眾號,每日一刷,輕松提升技術,斬獲各種offer: