踩坑点: 压测过程出现获取redis链接数慢的情况
    踩坑原因: 对应redis的配置不熟悉
    还原背景
    1、压测过程中当TPS达到一定位置时，开始上不去了，RT稳定在某一个值上下，核心服务CPU高，可以肯定的是存在某些方法执行慢，且RDS CPU和内存稳定 (show processlist未发现慢sql)，采用 Arthas 发现部分操作 Redis 的方法执行慢. 具体在 RedisTemplate.opsForValue.get 执行慢，进入里边一步一步的 trace ，最终定位在获取 链接慢 , 有时也存在执行慢的情况. 但大体上是获取 链接慢

    2、当时的环境

    • ECS Load开始飙高
    • 由于压测产生的日志较多，IO也产生了影响.
    • netstat 发现链接 Redis 服务器的 TIME_WAIT 也比较多.

    3、当时的我的思考是 :( 是不是jedis的问题
    **

    • 由于第一时间是核心服务的CPU飙升，打印堆栈发现是 Jedis 的读取线程 CPU 特别高，后续直接将 jedis 替换成 Lettuce , 线程CPU下滑. (服务本身也是非常吃CPU资源的)
    • 怀疑是不是 Redis 抗不住了，查看 Redis 的监控是此时的 QPS 达到2W+ , 进出口流量较高 (但是临时提升到48M发现并不是这个问题)，压测导致内存基本上打满了(也不是这个问题)，链接数虽然形成了相对飙升的情况，但是相对最大链接1w还是小case，并且使用 DMS 查询 redis 的数据的时候是非常快的
    • 日志打印特别频繁，怀疑IO有引起CPU高的可能性。

    **
    应对方案

    • 因为核心链路日志(使用logback)已经接入到ELK，但是还存在部分 log4j 实现的日志即未注释也没有处理，所以直接把这部分日志干掉. load有好转，但是RT依旧下不来.
    • Jedis 替换成 Lettuce

    4、源代码找问题.
    当时的配置

    1.     <bean id="fff" class="redis.clients.jedis.JedisPoolConfig">
    2.          <property name="maxIdle" value="8"/>
    3.          <property name="maxTotal" value="600"/>
    4.          <property name="maxWaitMillis" value="${redis.maxWaitMillis}"/>
    5.          <property name="testOnBorrow" value="${redis.testOnBorrow}"/>
    6.     </bean>

    4.1、本地降低配置启动执行

    使用 ab 进行压测 

    1. ab -r -n 1000 -c 调节这里的数字 -t 100 -s 30 'http://localhost:8082/redis'

    使用 netstat 查看链接情况

    1.  netstat -ant |grep 6379|grep

    根据 并发数设置的不同 产生的情况也是不一样的

    • 当并发数设置在5的时候，基本上没有 TIME_WAIT
    • 当并发数设置在100的时候， TIME_WAIT 疯长

    最后的源代码显示确实是在并发上去以后出现问题的，但是核心还是配置理解不到位.
    image.png
    org.springframework.data.redis.core.RedisTemplate#execute 

    1.     @Nullable
    2.     public <T> T execute(RedisCallback<T> action, boolean exposeConnection, boolean pipeline) {
    3.         //其他变量初始化
    4.         try {
    5.             //...获取链接执行请求
    6.             return postProcessResult(result, connToUse, existingConnection);
    7.         } finally {
    8.             //释放链接(问题在这里)
    9.             RedisConnectionUtils.releaseConnection(conn, factory, enableTransactionSupport);
    10.         }
    11.     }
    12. //    -------------我是漂亮的分割线-------------- RedisConnectionUtils
    13.     public static void releaseConnection(@Nullable RedisConnection conn, RedisConnectionFactory factory,
    14.             boolean transactionSupport) {
    16.         if (isConnectionTransactional(conn, factory)) {
    17.             //事务消息去掉
    18.         } else {
    19.             //这里的日志排查问题可以用到，具体使用方法不介绍
    20.             if (log.isDebugEnabled()) {
    21.                 log.debug("Closing Redis Connection.");
    22.             }
    23.             conn.close();//关闭内幕
    24.         }
    25.     }
    26. //    -------------我是漂亮的分割线--------------LettuceConnection
    27.     @Override
    28.     public void close() throws DataAccessException {
    29.         //...省略
    30.         if (asyncDedicatedConn != null) {
    31.             connectionProvider.release(asyncDedicatedConn);
    32.         }
    33.         //...省略
    34.     }
    35. //    -------------我是漂亮的分割线--------------LettucePoolingConnectionProvider
    36.     default void release(StatefulConnection<?, ?> connection) {
    37.         //...省略
    38.         pool.returnObject(connection);
    39.     }
    40. //  -------------我是漂亮的分割线--------------GenericObjectPool#归还数据到连接池
    41.     @Override
    42.     public void returnObject(final T obj) {
    43.         //...省略
    44.         final int maxIdleSave = getMaxIdle(); //获取maxIdle的配置 8
    45.         //idleObjects.size() 最大是200 但是肯定超过8，所以被destroy了
    46.         if (isClosed() || maxIdleSave > -1 && maxIdleSave <= idleObjects.size()) {
    47.             try {
    48.                 destroy(p);//socket.close
    49.             } catch (final Exception e) {
    50.                 swallowException(e);
    51.             }
    52.         } else {
    53.             //...省略
    54.         }
    55.         updateStatsReturn(activeTime);
    56.     }

    到这异步基本上真相大白了，当然也可以回头看看链接是如何创建的，看完后发现我们的配置其实是不合理的（当然跟本次的问题无关）

    这里的本质问题还是链接数配置的太低了，基本上生效的不会太多. 导致频繁的执行TCP的握手和挥手去建立和销毁链接

    最好的配置还是需要根据运行的环境来进行配置. 如果 TPS高，那就多配一点，maxIdle配置的多一点，maxTotal最大配置个200(tomcat的最大线程数)就够了，如果链接数浪费的起，那么maxIdle和maxTotal可以配置成200，minIdle配置的小一点，等等定时任务回收就可以了。

    最终分析得出来的原因是，链接数最终生效的只有8条，导致TPS高的时候大家都在等待Redis的链接，所以我们看到的问题就是获取链接数慢… 进而体现在TPS上不去。

    本地排查过程中遇到的问题(需要并发才能确定，但是并发会导致日志飙升)

    • ab压测过程中产生的debug日志太多了/流量太大，导致wireshark抓包基本无用
    • idle的含义不同，想当然的代入某个含义

    lettuce 配置问题

    • 默认是共享链接(只有一条TCP链接建立)，在TPS高的时候是不够的

      • tomcat# <property name="shareNativeConnection" value="false"/>
      • SpringBoot
        1. @Autowired //这种操作还是第一次看到 :)
        2. public void setLettuceConnectionFactory(LettuceConnectionFactory lettuceConnectionFactory){
        3.    lettuceConnectionFactory.setShareNativeConnection(false);
        4. }

    • 链接回收的配置问题