4

外部服务的连接参数合理设置问题

 2 years ago
source link: https://hellolyfing.github.io/2020/05/15/%E5%A4%96%E9%83%A8%E6%9C%8D%E5%8A%A1%E7%9A%84%E8%BF%9E%E6%8E%A5%E5%8F%82%E6%95%B0%E5%90%88%E7%90%86%E8%AE%BE%E7%BD%AE%E9%97%AE%E9%A2%98.html
Go to the source link to view the article. You can view the picture content, updated content and better typesetting reading experience. If the link is broken, please click the button below to view the snapshot at that time.
neoserver,ios ssh client

外部服务的连接参数合理设置问题

May 15, 2020

一、背景描述

现在的公司使用的阿里云的机器及服务，由于阿里云的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源码中的时间轮实现的

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


report

Recommend

About Joyk


Aggregate valuable and interesting links.
Joyk means Joy of geeK