文档章节

j2Cache线上异常问题排查记录

凯京技术团队
 凯京技术团队
发布于 06/04 18:00
字数 2367
阅读 2633
收藏 31

问题背景

开发反馈,线上有个服务在运行一段时间后,就会抛异常导致redis缓存不可用。项目使用了j2Caceh,异常是j2Cache的RedisCacheProvider抛出来的,如:

Exception in thread "main" redis.clients.jedis.exceptions.JedisException: Could not get a resource from the pool
	at redis.clients.util.Pool.getResource(Pool.java:51)
	at redis.clients.jedis.JedisPool.getResource(JedisPool.java:99)
	at net.oschina.j2cache.redis.RedisCacheProvider.getResource(RedisCacheProvider.java:51)
	at com.xczysoft.ltl.core.support.j2cache.J2CacheRedisCacheChannel.main(J2CacheRedisCacheChannel.java:66)
Caused by: java.util.NoSuchElementException: Timeout waiting for idle object
	at org.apache.commons.pool2.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:447)
	at org.apache.commons.pool2.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:361)
	at redis.clients.util.Pool.getResource(Pool.java:49)
	... 3 more

问题分析

从异常日志表象上看,很明显是由于jedis pool中没有资源了。当jedis pool没有资源,而客户端去申请连接时,框架预留了一个由用户控制的策略来处理,具体策略如下:

连接池参数 : blockWhenExhausted,有如下两种策略

  • true:阻塞等待maxWaitMillis时间(默认), 这个是默认的策略,当pool没有可用资源时,阻塞等待maxWaitMillis时间,这个值默认时间无限长的,连接池应该设置一个适当的等待时间
  • false:当无可用连接时,立即失败。

我们的服务并没有设置whenExhaustedAction 的参数,maxWait设置的是1500。也就是说当jedis pool没有可用资源时,获取连接的线程等待了1.5秒,1.5秒后还没有可用资源就抛异常了。

回到上面的问题,导致jedis pool原因有哪些呢?无外乎两点,如下:

  • 1、正常情况:程序并发高,导致偶发性的连接池无可用资源
  • 2、异常情况:连接池使用不当,当从连接池获取资源后,使用完时没有正常的释放资源,导致连接池取一个少一个,最后必然性的会抛出开头的异常

假设问题

结合上面对jedis pool的分析,而我们的服务并发度不高,默认连接池最大连接有8个,而且获取连接的线程在等待1.5秒后还是没有获取到线程,最重要的一点是,当程序跑到最后,获取不到连接的异常不在是偶发性的,

变成了必然性的事件了,那么根据上面这些分析,先假设问题就是由于程序中连接池使用不当导致的问题。程序使用jedis的地方是j2Cache,红薯开源的一个2阶缓存框架,很可能是红薯的锅。

小心求证

通过对问题的假设,我们需要在程序中找到从jedis pool中获取资源的代码,那首先需要找到初始化连接池的地方,j2Cache里是通过RedisCacheProvider来维护jedis pool的。下面是j2Cache里通过jedis pool的连接操作redis的代码,可以看到,非常规范,通过try,catch,finally将资源操作包起来了,并且在finally中释放了资源,保证资源一定会被释放

红薯表示这个锅我不背,肯定不是j2Cache的毛病了。可以看到RedisCacheProvider初始化连接池后,提供了一个静态方法getResource()用于获取连接,很可能是业务层面通过这个入口,拿到RedisCacheProvider里的连接了。后面继续找,定位到了一个非常有嫌疑的方法,代码如下:

    /**
     * 发送清除缓存的广播命令
     *
     * @param region: Cache region name
     */
    private void _sendClearCmd(String region) {
        // 发送广播
        Command cmd = new Command(Command.OPT_CLEAR_KEY, region, "");
        try (Jedis jedis = RedisCacheProvider.getResource()) {
            jedis.publish(SafeEncoder.encode(config.getProperty("redis.channel_name")), cmd.toBuffers());
        } catch (Exception e) {
            log.error("Unable to clear cache,region=" + region, e);
        }
    }

可以看到,这是一段和j2Cache相关的代码,但是不是红薯的框架内的,是我们开发在接入j2Cache时配置的一个缓存通道内的一段代码。问题就出在通过

RedisCacheProvider.getResource()拿到jedis对象后,使用完,并没有释放。

问题重现

上面基本定位到问题了,下面我们模拟下发生的问题的场景,代码逻辑和上面的类似,我们初始化一个连接池后,在一个for循环中,模拟多次获取连接但是不释放,如:

    public static void main(String[] args) throws Exception {
        Properties properties = ResourceUtil.getResourceAsProperties("app.properties", true);
        new J2CacheRedisCacheChannel("j2Cache 666", properties);
        for (int i = 1; i <= 8; i++) {
            Jedis jedis = RedisCacheProvider.getResource();
            try {
                jedis.get("kl");
            } catch (Exception e) {
                log.error("Unable to clear cache,region=" + null, e);
            }
            System.out.println("第" + i + "次运行");
        }
    }

上面代码的运行效果如:

而且是必然出现的,在第八次的时候,因为没有可用的连接,导致程序在等待1.5秒后抛出了异常

问题解决

综上,我们可以肯定是由于这里的代码使用不规范,导致的连接池连接泄漏了。代码修改也非常简单,在finally中判断下jeids对象是否为null,不为null则调用其close方法,将资源回收即可。

上文所述场景中有个地方埋了一个小彩蛋,感兴趣的小伙伴可以找下,在下方留言交流。

问题后记-下面才是真正的原因

你以为就上面的就这么完了,还没呢,待续ing

其实上面获取jedis资源的代码是没有问题,刚开始忽略了一个细节,try (Jedis jedis = RedisCacheProvider.getResource()) 。获取资源的动作是放在try()里的,java1.7引入了try-with-resources

语义,我们使用的jedis版本已经实现了JDK的AutoCloseable接口。所以,上面这段代码在编译器编译后会变成如下的样子:

private void _sendEvictCmd(String region, Object key) {
    Command cmd = new Command((byte)1, region, key);
 
    try {
        Jedis jedis = RedisCacheProvider.getResource();
        Throwable var5 = null;
 
        try {
            jedis.publish(SafeEncoder.encode(this.config.getProperty("redis.channel_name")), cmd.toBuffers());
        } catch (Throwable var15) {
            var5 = var15;
            throw var15;
        } finally {
            if (jedis != null) {
                if (var5 != null) {
                    try {
                        jedis.close();
                    } catch (Throwable var14) {
                        var5.addSuppressed(var14);
                    }
                } else {
                    jedis.close();
                }
            }
 
        }
    } catch (Exception var17) {
        log.error("Unable to delete cache,region=" + region + ",key=" + key, var17);
    }
 
}

可以看到,编译器自动帮我们织入了想要在finally代码块内关闭连接的动作。

重新假设

如果不是连接泄漏导致的,那么肯定是并发问题了,最终的异常是j2Cache抛出来的,从j2Cache里获取连接的地方如下:

可以看到最上面红框里的是之前说的有问题,其实没有问题,他们都被包在了try里面了。中间的是红薯框架内部用的,都手动释放连接了。最后一个连接有点小问题,SeqServiceImpl是spring管理的一个实例,

因为是单例的实例,所以这里只会长期占用一个连接。除了这里占用了一个连接,上面三个在try里的连接,其中一个是订阅redis消息的,代码如下:


thread_subscribe = new Thread(new Runnable() {
    @Override
    public void run() {
        try (Jedis jedis = RedisCacheProvider.getResource()) {
            jedis.subscribe(J2CacheRedisCacheChannel.this, SafeEncoder.encode(config.getProperty("redis.channel_name")));
        }
    }
});

注意这个jedis.subscribe()。其实是个阻塞操作。也就是说即使编辑器给这个地方加上了资源释放的代码,在订阅不出问题的情况下,也跑不到资源释放的地方。所以这里也会长期占用一个连接。

那么我们在程序里可用的连接数=(最大连接数-两个长期占用连接)=(8-2)=6个

从异常信息获取点有用信息,最终发现,抛出连接不可用的代码有共性,都指向了一个类,但是是两个方法,如:

最终跟踪代码发现,这个两个方法是给鉴权拦截器调用的,拦截器会拦截每个请求,代码语义类似下面,

@Override
public boolean preHandle(HttpServletRequest request, HttpServletResponse response,
                         Object handler) throws Exception {
    RunResult<ApiSession> runResult = sysApiService.auth(null);
    sysApiService.update("", runResult.getData(), request);
    return super.preHandle(request, response, handler);
}

也就是每个请求都至少会对redis操作两次,在没有完成之前都不会释放资源。

在看看抛异常的时间点的服务访问情况,在日志平台将时间限定在2019-06-03 17:45~2019-06-03 17:46 ,搜索结果如下:

从06-03 17:45:49 到 06-03 17:45:56 日志总条数299条。每秒请求数=(299/56-49)=42 。omygad的,连接池只有6个可用连接完全不够用。这回真的石锤了。

最终解决

设置连接池的maxTotal参数即可,但是有个问题是,这个项目使用的j2Cache的版本比较老,代码的配置信息限定死了就那么个几个,而且没有预留maxTotal的设置。红薯的初始化连接池的代码如下:

  public void start(Properties props) throws CacheException {
      JedisPoolConfig config = new JedisPoolConfig();
       
      host = getProperty(props, "host", "127.0.0.1");
      password = props.getProperty("password", null);
       
      port = getProperty(props, "port", 6379);
      timeout = getProperty(props, "timeout", 2000);
      database = getProperty(props, "database", 0);
 
      config.setBlockWhenExhausted(getProperty(props, "blockWhenExhausted", true));
      config.setMaxIdle(getProperty(props, "maxIdle", 10));
      config.setMinIdle(getProperty(props, "minIdle", 5));
//    config.setMaxActive(getProperty(props, "maxActive", 50));
      config.setMaxWaitMillis(getProperty(props, "maxWait", 100));
      config.setTestWhileIdle(getProperty(props, "testWhileIdle", false));
      config.setTestOnBorrow(getProperty(props, "testOnBorrow", true));
      config.setTestOnReturn(getProperty(props, "testOnReturn", false));
      config.setNumTestsPerEvictionRun(getProperty(props, "numTestsPerEvictionRun", 10));
      config.setMinEvictableIdleTimeMillis(getProperty(props, "minEvictableIdleTimeMillis", 1000));
      config.setSoftMinEvictableIdleTimeMillis(getProperty(props, "softMinEvictableIdleTimeMillis", 10));
      config.setTimeBetweenEvictionRunsMillis(getProperty(props, "timeBetweenEvictionRunsMillis", 10));
      config.setLifo(getProperty(props, "lifo", false));
 
      pool = new JedisPool(config, host, port, timeout, password, database);
       
   }

怎么办类,组件代码不好改啊,java的黑科技反射解决问题,不走寻常路,不使用start方法初始化连接池,直接自己初始化一个连接池设置给pool属性。伪代码如下:

JedisPoolConfig config = new JedisPoolConfig();
config.setMaxTotal(50);
JedisPool pool = new JedisPool(config, host, port, timeout, password, database);
Field field = RedisCacheProvider.class.getDeclaredField("pool");
field.setAccessible(true);
field.set(RedisCacheProvider.class, pool);

作者简介:

陈凯玲,2016年5月加入凯京科技。现任凯京科技研发中心架构&运维部架构组经理,救火队队长。独立博客KL博客(http://www.kailing.pub)博主。

© 著作权归作者所有

凯京技术团队
粉丝 63
博文 33
码字总数 65780
作品 1
浦东
架构师
私信 提问
加载中

评论(15)

沧海一刀
沧海一刀
eeeee
G7
G7
激凸擦车,摩擦摩擦,似魔鬼的步伐...........
h
heike07
这篇文章不错
微雨心晴
微雨心晴

引用来自“红薯”的评论

最喜欢吐槽 #J2Cache# 的文章了,明天首页推荐。
有什么改进的欢迎提交 PR 到 j2cache 哈:)

@红薯 建议特别发个开源内裤和霸王给撸主三:分析问题多了五姑娘都没有用得用开源内裤,分析问题多了头发就少了得用红薯专用洗发水了。
tritonNeri
tritonNeri
身临其境,好文
司徒永超
司徒永超
开头的 j2Cache 写成了 j2Caceh
HostSugar
HostSugar
发现不知道啥时候早关注了http://www.kailing.pub😄
NotFound403
NotFound403
这是一篇充满了py交易的文章😆
Jensen_Lin
Jensen_Lin
抽丝剥茧,层层分析,好文。
IdleMan
IdleMan
大家都用🐔二缓存吗
使用 fastjson 实现类型无关的对象序列化

今天跟 fastjson 作者 @wenshao 聊了会才找到 fastjson 如何实现类型无关的对象序列化 代码如下: J2Cache 已经新增了这个特性,详情请看这里。 J2Cache 使用 JSON 进行缓存数据序列化的方式...

红薯
2018/08/08
548
0
J2Cache 2.2.1 正式版发布,开源中国两级缓存框架

J2Cache 2.2.1 正式版发布了。J2Cache 是 OSChina 目前正在使用的两级缓存框架。第一级缓存使用 Ehcache,第二级缓存使用 Redis 。由于大量的缓存读取会导致 L2 的网络成为整个系统的瓶颈,因...

周其
2018/01/10
973
5
J2Cache 2.5.5 发布,完善对 Sentinel 的 pub/sub 支持

J2Cache 2.5.5 发布了,该版本主要改进内容包括: 完善对 Redis Sentinel 的 pub/sub 支持 修复了 json 序列化不支持 java.sql.Date 和 java.sql.Timestamp 的问题 修复 Spring Boot 模块的序...

红薯
2018/09/06
1K
12
J2Cache 2.2.0-beta 发布,开源中国两级缓存框架

J2Cache 2.2.0-beta 发布,J2Cache 是 OSChina 目前正在使用的两级缓存框架。第一级缓存使用 Ehcache,第二级缓存使用 Redis 。由于大量的缓存读取会导致 L2 的网络成为整个系统的瓶颈,因此...

周其
2018/01/08
3K
21
前两天网站访问慢的问题定位过程以及最终解决办法

前提说明:目前开源中国社区在做改版,因此网站同时存在新旧两种不同的版面,例如个人空间就是新的系统。因此整个网站包含两套系统,改版前和改版后,我们把改版前叫老系统,把改版后叫新系统...

红薯
2018/08/16
6K
87

没有更多内容

加载失败,请刷新页面

加载更多

nproc systemd on CentOS 7

Increasing nproc for processes launched by systemd on CentOS 7 Ask Question I have successfully increased the nofile and nproc value for the local users, but I couldn't find a p......

MtrS
26分钟前
1
0
了解微信小程序下拉刷新功能

小程序提供了这个事件。 onPullDownRefresh() 监听用户下拉刷新事件。 如果要开启下拉刷新功能,要先到json配置: "enablePullDownRefresh":true 配置后下拉有反应了但是没有加载效果,在onP...

oixan__
51分钟前
2
0
springmvc java对象转json,上传下载(未完)拦截器Interceptor以及源码解析(未完待续)

package com.atguigu.my.controller;import java.util.Collection;import org.springframework.beans.factory.annotation.Autowired;import org.springframework.stereotype.Contr......

architect刘源源
今天
29
0
[日更-2019.5.24、25、26] Android系统中的Binder通信机制分析(一)--servicemanager

声明 其实对于Android系统Binder通信的机制早就有分析的想法,记得去年6、7月份Mr.Deng离职期间约定一起对其进行研究的,但因为我个人问题没能实施这个计划,留下些许遗憾... 最近,刚好在做...

Captain_小馬佩德罗
昨天
24
0
聊聊dubbo的DataStore

序 本文主要研究一下dubbo的DataStore DataStore dubbo-2.7.2/dubbo-common/src/main/java/org/apache/dubbo/common/store/DataStore.java @SPI("simple")public interface DataStore { ......

go4it
昨天
3
0

没有更多内容

加载失败,请刷新页面

加载更多

返回顶部
顶部