一、背景描述

现在的公司使用的阿里云的机器及服务，由于阿里云的Redis不可用导致我们整站的服务出现不可用。本文讨论的重点不是这个，而是，当阿里云的Redis服务恢复之后，我司整站的服务都开始快速恢复了，但我负责的基础平台的一个交易核心服务却仍然RT很高，没法快速恢复。当时情况紧急，优先选择了重启服务，而服务重启之后这个核心服务的RT也就降下来了。很奇怪的现象，所以这里复盘记录一下。

二、第一个疑惑：交易下单的HTTP服务RT居高不下

现象

交易C端Session服务连接Redis严重超时问题（18秒+），从我司的全链路调用监控看到的问题现场如下：

疑问

为啥Redis耗时会达到18s+？在Redis连接里，明明设置了超时时间了，证据如下：

@Bean(name = Constants.SPRING_BEAN_PREFIX + "AuthCacheClient")
public AuthCacheClient authCacheClient() {
    JedisConfig jedisConfig = new JedisConfig();
    jedisConfig.setHost(confReader.get("user-session.host"));
    jedisConfig.setPort(Integer.valueOf(confReader.get("user-session.port")));
    jedisConfig.setPassword(confReader.get("user-session.password"));
    jedisConfig.setMaxIdle(30);
    jedisConfig.setMaxTotal(50);
    // 下面这一行已经设置了超时时间
    jedisConfig.setTimeout(1000);
    return new AuthCacheClientImpl(jedisConfig);
}

接着去看了下Jedis的源码，发现Jedis配置中的超时时间有两类，需要特别注意：

timeout: 用于端到端连接的超时时间设定
maxWaitMillis：由于Jedis也是使用的线程池化方案（使用了apache的池化代码），该参数用于设置：从线程池中获取一个空闲线程时的等待时间。默认值-1，也就是阻塞式等待，直到有可用线程。当然该参数生效也是有前提开关的，代码详见org.apache.commons.pool2.impl.GenericObjectPool#borrowObject(long)

原因解释

所以上面代码示例的超时配置并不完整，而且有较大的安全隐患，最好主动设置下maxWaitMillis参数

jedisConfig.setMaxWaitMillis(1000);

测试验证

通过编写测试用例，验证了上述描述是正确的

@Test
public void testTimeoutParam() {
    JedisConfig jedisConfig = new JedisConfig();
    jedisConfig.setHost(redisXconfReader.get("user-session.host"));
    jedisConfig.setPort(Integer.valueOf(redisXconfReader.get("user-session.port")));
    jedisConfig.setPassword(redisXconfReader.get("user-session.password"));
    jedisConfig.setMaxIdle(1);
    jedisConfig.setMaxTotal(1); // 线程池中只放入1个工作线程
    jedisConfig.setTimeout(1000);
    jedisConfig.setMaxWaitMillis(5000); // 不加这一行代码时，最后一行代码会一直等待，直到唯一的工作线程从sleep中返回
    AuthCacheClientImpl authCacheClient = new AuthCacheClientImpl(jedisConfig);
 
    ExecutorService executorService = Executors.newSingleThreadExecutor();
    executorService.submit(() -> {
        authCacheClient.tryWithResource((jedis) -> {
            // 啥也不做，占用唯一一个Jedis线程
            safeSleep(600 * 1000);
            return null;
        });
    });
 
    safeSleep(100); // 保证上一步代码先开始执行
 
    // 不设置maxWaitMillis参数，则本行代码将一直等待可用Jedis线程。设置后则会等待给定时间(5000ms)后抛出超时异常
    authCacheClient.getFromCache("AnyKey".getBytes());
}

三、第二个疑惑：交易下单的DubboRPC服务RT居高不下

现象

从日志平台能够看到简单的Model查询接口，出现了10s+的延迟(elapsed附近)。大量类似查询导致Dubbo线程池被打满，无法正常服务。

疑问

为啥简单的Model查询会超时，而且二并未发现Mysql慢查询日志？

从生产环境的错误日志里找到答案: Hbase无法连接了。因为该Dubbo接口有热库冷库依次查询的逻辑，如果从热库Mysql查不到数据，会去冷库Hbase里再查一遍。但Hbase无法连接为啥会导致如此高的延迟？

[2021-09-28 10:14:59] [WARN] [DubboServerHandler-10.32.146.61:20880-thread-166] [] o.a.h.hbase.client.ConnectionUtils - Can not resolve hb-bp196k2oz218p5zeh-core-002.hbase.rds.aliyuncs.com, please check your network
java.net.UnknownHostException: hb-bp196k2oz218p5zeh-core-002.hbase.rds.aliyuncs.com
    at java.net.InetAddress.getAllByName0(InetAddress.java:1281)
    at java.net.InetAddress.getAllByName(InetAddress.java:1193)
    at java.net.InetAddress.getAllByName(InetAddress.java:1127)
    at java.net.InetAddress.getByName(InetAddress.java:1077)
    at org.apache.hadoop.hbase.client.ConnectionUtils.getStubKey(ConnectionUtils.java:233)
    at org.apache.hadoop.hbase.client.ConnectionImplementation.getClient(ConnectionImplementation.java:1192)
    at org.apache.hadoop.hbase.client.ClientServiceCallable.setStubByServiceName(ClientServiceCallable.java:44)
    at org.apache.hadoop.hbase.client.RegionServerCallable.prepare(RegionServerCallable.java:229)
    at org.apache.hadoop.hbase.client.RpcRetryingCallerImpl.callWithRetries(RpcRetryingCallerImpl.java:105)

原因解释

去查看代码才发现，业务代码初始化时，Hbase未设置各项连接超时参数，导致连接异常时无限等待。下图左侧为Hbase配置的原代码，右侧为添加了各项超时之后的代码

测试验证

按照上图添加了各项超时配置后，让DBA配合把测试环境机器移除Hbase的连接白名单，来验证无法建立连接时的超时配置是否生效。手动invoke dubbo接口发现确实会3s后自动超时并报错，修改达到效果。按照预期的超时报错日志如下

Caused by: java.io.IOException: Call to hb-bp1ya00iwt363g267-core-001.hbase.rds.aliyuncs.com/192.168.103.236:16020 failed on local exception: org.apache.hadoop.hbase.ipc.CallTimeoutException: Call id=14, waitTime=3008, rpcTimeout=2997
at org.apache.hadoop.hbase.ipc.IPCUtil.wrapException(IPCUtil.java:180)
at org.apache.hadoop.hbase.ipc.AbstractRpcClient.onCallFinished(AbstractRpcClient.java:390)
at org.apache.hadoop.hbase.ipc.AbstractRpcClient.access$100(AbstractRpcClient.java:95)
at org.apache.hadoop.hbase.ipc.AbstractRpcClient$3.run(AbstractRpcClient.java:410)
at org.apache.hadoop.hbase.ipc.AbstractRpcClient$3.run(AbstractRpcClient.java:406)
at org.apache.hadoop.hbase.ipc.Call.setTimeout(Call.java:96)
at org.apache.hadoop.hbase.ipc.RpcConnection$1.run(RpcConnection.java:200)
at org.apache.hbase.thirdparty.io.netty.util.HashedWheelTimer$HashedWheelTimeout.expire(HashedWheelTimer.java:663)

另外从最后一行报错也可以看出，hbase的超时触发也是使用了Netty源码中的时间轮实现的

总结

准确理解和设置各项中间件服务的超时时间非常有必要！