问题复盘:一个Redisson驱动源码BUG

今天来看一个之前遇到的问题。

前段时间,生产环境的一个模块偶发性出现不工作的情况,最后定位到是模块中使用的Redisson源码中的一个BUG。

还顺便给Redisson增加了一个测试用例:

https://github.com/redisson/redisson/commit/fdde5d8bcb3259d7b558993fc2e449ef5cc0385a

Redisson是Redis官方推荐的Java版的Redis客户端,是一个在Redis的基础上实现的Java驻内存数据网格(In-Memory Data Grid),在GitHub上有16.3K的star。

图片

Redisson 提供了许多 Features ,这次出问题的是业务模块中使用到的分布式调度任务服务(Scheduler Service),使用的Redisson 版本是3.14.1 。

本文主要是问题的一个复盘,更重要的是记录下处理过程中的思路。如果有更好的定位手段欢迎交流一下。

01 拿到问题后积极收集相关数据,合理分析,大胆假设

接到问题反馈后,先去查看了线上的业务日志情况,发现已经没有处理业务线程输出日志,正常情况下只要服务正常运行都是会有相关记录的,所以初步怀疑是某个方法将线程池的所有线程都阻塞了。

因为已经让运维的同学开了新的服务机器保证用户使用,将这台问题机器暂时保留作为定位用,所以 可以在当前机器上使用 arthas 查看当前服务的一个线程情况。

Arthas 是 Alibaba 开源的Java诊断工具,可以比较方便在生产环境机器上进行问题的定位和诊断。

更多介绍可以查看官方介绍:

https://arthas.aliyun.com/doc/

[arthas@1440]$ thread -all
Threads Total: 332, NEW: 0, RUNNABLE: 149, BLOCKED: 0, WAITING: 146, TIMED_WAITING: 25, TERMINATED: 0, Internal threads: 12                                            
ID     NAME                                      GROUP                PRIORITY      STATE        %CPU          DELTA_TIME    TIME          INTERRUPTED   DAEMON          
...           
143485 pool-4-thread-112353                      main                 5             WAITING      0.0           0.000         0:41.813      false         false         
144056 pool-4-thread-112725                      main                 5             WAITING      0.0           0.000         0:0.655       false         false         
144064 pool-4-thread-112731                      main                 5             WAITING      0.0           0.000         0:6.117       false         false         
144314 pool-4-thread-112875                      main                 5             WAITING      0.0           0.000         0:15.230      false         false         
144345 pool-4-thread-112885                      main                 5             WAITING      0.0           0.000         5:11.817      false         false         
144506 pool-4-thread-112905                      main                 5             WAITING      0.0           0.000         17:3.553      false         false         
144529 pool-4-thread-112914                      main                 5             WAITING      0.0           0.000         115:34.837    false         false         
144534 pool-4-thread-112915                      main                 5             WAITING      0.0           0.000         167:40.361    false         false         
144536 pool-4-thread-112916                      main                 5             WAITING      0.0           0.000         13:45.058     false         false         
144539 pool-4-thread-112917                      main                 5             WAITING      0.0           0.000         101:58.574    false         false         
144545 pool-4-thread-112918                      main                 5             WAITING      0.0           0.000         22:18.870     false         false         
...

[arthas@1440]$ thread 143485
"pool-4-thread-112353" Id=143485 WAITING on io.netty.util.concurrent.ImmediateEventExecutor$ImmediatePromise@efc8da9
    at java.lang.Object.wait(Native Method)
    -  waiting on io.netty.util.concurrent.ImmediateEventExecutor$ImmediatePromise@efc8da9
    at java.lang.Object.wait(Object.java:502)
    at io.netty.util.concurrent.DefaultPromise.await(DefaultPromise.java:252)
    at org.redisson.misc.RedissonPromise.await(RedissonPromise.java:110)
    at org.redisson.misc.RedissonPromise.await(RedissonPromise.java:35)
    at org.redisson.command.CommandAsyncService.get(CommandAsyncService.java:139)
    at org.redisson.RedissonExecutorService.cancelTask(RedissonExecutorService.java:1036)
    ...
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at java.lang.Thread.run(Thread.java:748)

查看对应源码可以看到其实这里实际调用的是一个异步方法,但根据堆栈信息反推不出问题根本原因。

public boolean cancelTask(String taskId) {
    return commandExecutor.get(cancelTaskAsync(taskId));
}

可以看出,是在取消定时任务的地方阻塞了。该业务模块使用了定时模块,比如说60s后执行某个动作,但是这个定时是能被取消的,一个特定的请求会触发取消掉这个定时任务,这时候就需要调用 cancelTask方法,但是在业务上线之前肯定都是经过测试的,并且已经在线上跑了快一年了,也没有出现过问题。

通过对问题时间点附近的业务日志进行分析,发现一个异常的点,在调用cancelTask发生阻塞线程的上下文中,都是在60s定时时间到,开始执行定时任务的时候触发了取消定时任务。通过往前查找相似的业务日志, 发现这个特殊情况下阻塞线程也是概率出现的。

02 在测试环境根据推测简化代码,提高复现概率,确认问题出现步骤

根据生产环境中收集到的信息和对问题的推测,在测试环境下 去模拟复现问题,确认问题复现步骤。但是在之前, 可以对测试环境做一些精简处理,比如说将模块的业务线程池总线程数量减少,提高复现效率。

在测试环境验证的过程中,发现了几个有意思的点:

1、取消定时任务的时机非常重要. 必须是该定时任务正在执行中,可以是已经由Redisson开始反序列化任务对象,也可以是已经在执行定时的业务代码,但是不能是任务已经执行完毕

2、通过延长定时任务处理时间可以提高问题复现概率

3、定时任务的业务代码中添加了延时后,取消任务后若定时任务还有超过3s的时间,就会抛出InterruptedException异常,取消任务也是成功的,不会阻塞线程

因为能在测试环境直接必现问题,所以是可以在测试环境的跑服务的机器上打开调试端口,通过ssh的反向代理让本机进入远程调试模式,进一步确认异步方法的阻塞位置。

图片

03 在本地环境提炼出问题的测试用例,进一步分析

通过以上操作,基本已经能确定问题的复现步骤了,可以将问题部分摘出来写成测试用例,一方面能反馈给官方,另一方面也能在本地进一步确认问题的原因。

代码如下:

public class SchedulerServiceExamples {
    private static final Logger LOG = LoggerFactory.getLogger(SchedulerServiceExamples.class);

    public static void main(String[] args) throws InterruptedException {
        Config config = new Config();
        config.useSingleServer().setAddress("redis://127.0.0.1:6379");

        RedissonClient redisson = Redisson.create(config);

        RedissonNodeConfig nodeConfig = new RedissonNodeConfig(config);
        nodeConfig.setExecutorServiceWorkers(Collections.singletonMap("myExecutor", 5));
        RedissonNode node = RedissonNode.create(nodeConfig);
        node.start();

        RScheduledExecutorService e = redisson.getExecutorService("myExecutor");
        String taskId = redisson.getExecutorService("myExecutor").schedule(new RunnableTask(), 2000, TimeUnit.MILLISECONDS).getTaskId();
        Thread.sleep(5500);

        LOG.info("xxxx start cancel task {}", taskId);
        e.cancelTask(taskId);
        LOG.info("yyyy end cancel task {}", taskId);
    }

    public static class RunnableTask implements Runnable, Serializable {

        private static final Logger LOG = LoggerFactory.getLogger(RunnableTask.class);

        @Override
        public void run() {
            LOG.info("Task start...");
            try {
                Thread.sleep(1000);
                LOG.info("Task running 1 ...");
                Thread.sleep(1000);
                LOG.info("Task running 2 ...");
                Thread.sleep(1000);
                LOG.info("Task running 3 ...");
                Thread.sleep(1000);
                LOG.info("Task running 4 ...");
            } catch (InterruptedException interruptedException) {
                LOG.info("Task interruptedException");
            }
        }

    }

可以在执行完取消任务的下一行日志设置断点,可以看到并不会执行到36行。

图片

继续往下定位, 能确认是在 scheduleCheck 中死循环了,因为当前进入了异常分支

图片

继续看下removeAsync方法

图片

removeOperationAsync 做了做了什么事情呢?其实就是去获取hash 里面的序列化任务。

protected RFuture<V> removeOperationAsync(K key) {
    String name = getName(key);
    return commandExecutor.evalWriteAsync(name, codec, RedisCommands.EVAL_MAP_VALUE,
            "local v = redis.call('hget', KEYS[1], ARGV[1]); "
            + "redis.call('hdel', KEYS[1], ARGV[1]); "
            + "return v",
            Collections.singletonList(name), encodeMapKey(key));
}

但是在此时任务对应的 hashmap key 已经被删除了,可以从输出的日志中查看到相应输出

19:55:10.852 [redisson-netty-5-17] DEBUG org.redisson.command.RedisExecutor - connection released for command (EVAL) and params [local value = redis.call('zscore', KEYS[2], ARGV[1]); if (value ~= false and tonumber(value) < tonum..., 7, {myExecutor:org.redisson.executor.RemoteExecutorService}:tasks, {myExecutor:org.redisson.executor.RemoteExecutorService}:expiration, {myExecutor:org.redisson.executor.RemoteExecutorService}:counter, {myExecutor:org.redisson.executor.RemoteExecutorService}:status, {myExecutor:org.redisson.executor.RemoteExecutorService}:retry-interval, {myExecutor:org.redisson.executor.RemoteExecutorService}:termination-topic, {myExecutor:org.redisson.executor.RemoteExecutorService}:scheduler, 0185996c68c89d47cc0da91d38ebc87d02, ...] from slot NodeSource [slot=0, addr=null, redisClient=null, redirect=null, entry=null] using connection RedisConnection@334656297 [redisClient=[addr=redis://127.0.0.1:6379], channel=[id: 0x86bb7257, L:/127.0.0.1:60572 - R:/127.0.0.1:6379], currentCommand=CommandData [promise=RedissonPromise [promise=ImmediateEventExecutor$ImmediatePromise@710d6403(success: RemoteServiceRequest [requestId=0185996c68c89d47cc0da91d38ebc87d02, methodName=scheduleRunnable, signature=[J@538349a2, args=[org.redisson.executor.params.ScheduledParameters@5333e8cd], options=RemoteInvocationOptions[ackTimeoutInMillis=null, executionTimeoutInMillis=3600000], date=1619956508690])], command=(EVAL), params=[local value = redis.call('zscore', KEYS[2], ARGV[1]); if (value ~= false and tonumber(value) < tonum..., 7, {myExecutor:org.redisson.executor.RemoteExecutorService}:tasks, {myExecutor:org.redisson.executor.RemoteExecutorService}:expiration, {myExecutor:org.redisson.executor.RemoteExecutorService}:counter, {myExecutor:org.redisson.executor.RemoteExecutorService}:status, {myExecutor:org.redisson.executor.RemoteExecutorService}:retry-interval, {myExecutor:org.redisson.executor.RemoteExecutorService}:termination-topic, {myExecutor:org.redisson.executor.RemoteExecutorService}:scheduler, 0185996c68c89d47cc0da91d38ebc87d02, ...], codec=org.redisson.codec.MarshallingCodec]]
19:55:10.861 [redisson-6-6] INFO com.neo.web.SchedulerServiceExamples$RunnableTask - Task start...
19:55:11.861 [redisson-6-6] INFO com.neo.web.SchedulerServiceExamples$RunnableTask - Task running 1 ...
19:55:12.862 [redisson-6-6] INFO com.neo.web.SchedulerServiceExamples$RunnableTask - Task running 2 ...
19:55:13.426 [redisson-netty-2-21] DEBUG org.redisson.connection.DNSMonitor - Request sent to resolve ip address for master host: 127.0.0.1
19:55:13.429 [redisson-netty-2-20] DEBUG org.redisson.connection.DNSMonitor - Resolved ip: /127.0.0.1 for master host: 127.0.0.1
19:55:13.575 [redisson-netty-5-21] DEBUG org.redisson.connection.DNSMonitor - Request sent to resolve ip address for master host: 127.0.0.1
19:55:13.576 [redisson-netty-5-20] DEBUG org.redisson.connection.DNSMonitor - Resolved ip: /127.0.0.1 for master host: 127.0.0.1
19:55:13.862 [redisson-6-6] INFO com.neo.web.SchedulerServiceExamples$RunnableTask - Task running 3 ...
19:55:13.886 [redisson-timer-7-1] DEBUG org.redisson.command.RedisExecutor - acquired connection for command (EVAL) and params [local v = redis.call('hget', KEYS[1], ARGV[1]); redis.call('hdel', KEYS[1], ARGV[1]); return v, 1, {myExecutor:remote}:cancel-request, PooledUnsafeDirectByteBuf(ridx: 0, widx: 34, cap: 256)] from slot NodeSource [slot=0, addr=null, redisClient=null, redirect=null, entry=null] using node /127.0.0.1:6379... RedisConnection@956171700 [redisClient=[addr=redis://127.0.0.1:6379], channel=[id: 0xc1cbe7cf, L:/127.0.0.1:60568 - R:/127.0.0.1:6379], currentCommand=null]
19:55:13.888 [redisson-netty-5-14] DEBUG org.redisson.command.RedisExecutor - connection released for command (EVAL) and params [local v = redis.call('hget', KEYS[1], ARGV[1]); redis.call('hdel', KEYS[1], ARGV[1]); return v, 1, {myExecutor:remote}:cancel-request, PooledUnsafeDirectByteBuf(ridx: 0, widx: 34, cap: 256)] from slot NodeSource [slot=0, addr=null, redisClient=null, redirect=null, entry=null] using connection RedisConnection@956171700 [redisClient=[addr=redis://127.0.0.1:6379], channel=[id: 0xc1cbe7cf, L:/127.0.0.1:60568 - R:/127.0.0.1:6379], currentCommand=CommandData [promise=RedissonPromise [promise=ImmediateEventExecutor$ImmediatePromise@954380a(success)], command=(EVAL), params=[local v = redis.call('hget', KEYS[1], ARGV[1]); redis.call('hdel', KEYS[1], ARGV[1]); return v, 1, {myExecutor:remote}:cancel-request, PooledUnsafeDirectByteBuf(ridx: 0, widx: 34, cap: 256)], codec=org.redisson.codec.CompositeCodec@85fd4fb7]]
19:55:14.208 [main] INFO com.neo.web.SchedulerServiceExamples - xxxx start cancel task 0185996c68c89d47cc0da91d38ebc87d02

所以导致每3s进入一次 scheduleCheck 检查

将问题和测试用例反馈给redisson官方后,在3.15.1版本已经将该问题修复,可以看下官方的解决办法

合入记录:

https://github.com/redisson/redisson/commit/fdde5d8bcb3259d7b558993fc2e449ef5cc0385a

主要就是在异常分支添加了对任务hash的一个判断

// 3.15.1
private void scheduleCancelResponseCheck(String mapName, RequestId requestId, RPromise<RemoteServiceCancelResponse> cancelResponse) {
        commandExecutor.getConnectionManager().newTimeout(timeout -> {
            if (cancelResponse.isDone()) {
                return;
            }

            RMap<String, RemoteServiceCancelResponse> canceledResponses = getMap(mapName);
            RFuture<RemoteServiceCancelResponse> future = canceledResponses.removeAsync(requestId.toString());
            future.onComplete((response, ex) -> {
                if (ex != null) {
                    scheduleCancelResponseCheck(mapName, requestId, cancelResponse);
                    return;
                }

                if (response == null) {
                    RFuture<Boolean> f = hasTaskAsync(requestId.toString());
                    f.onComplete((r, e) -> {
                        if (e != null || r) {
                            scheduleCancelResponseCheck(mapName, requestId, cancelResponse);
                            return;
                        }

                        RemoteServiceCancelResponse resp = new RemoteServiceCancelResponse(requestId.toString(), false);
                        cancelResponse.trySuccess(resp);
                    });
                } else {
                    cancelResponse.trySuccess(response);
                }
            });
        }, 3000, TimeUnit.MILLISECONDS);
    }

// 3.14.1
protected <T> void scheduleCheck(String mapName, RequestId requestId, RPromise<T> cancelRequest) {
        commandExecutor.getConnectionManager().newTimeout(new TimerTask() {
            @Override
            public void run(Timeout timeout) throws Exception {
                if (cancelRequest.isDone()) {
                    return;
                }

                RMap<String, T> canceledRequests = getMap(mapName);
                RFuture<T> future = canceledRequests.removeAsync(requestId.toString());
                future.onComplete((request, ex) -> {
                    if (cancelRequest.isDone()) {
                        return;
                    }
                    if (ex != null) {
                        scheduleCheck(mapName, requestId, cancelRequest);
                        return;
                    }
                    
                    if (request == null) {
                        scheduleCheck(mapName, requestId, cancelRequest);
                    } else {
                        cancelRequest.trySuccess(request);
                    }
                });
            }
        }, 3000, TimeUnit.MILLISECONDS);
    }

解决问题的过程就是层层抽丝剥茧,硬着头皮干就完事了!

下班了下班了~

【推荐阅读】

1、京东云无线宝怎么设置收益高?一个不需要光猫后台超级账号密码的方法

2、两台主机、多台主机怎么共用键鼠?Windows、Mac OS、Linux 多系统怎么共用键鼠?

3、记录一下小米6解BL锁,获取ROOT权限

热门文章

暂无图片
编程学习 ·

那些年让我们目瞪口呆的bug

程序员一生与bug奋战&#xff0c;可谓是杀敌无数&#xff0c;见怪不怪了&#xff01;在某知识社交平台中&#xff0c;一个“有哪些让程序员目瞪口呆的bug”的话题引来了6700多万的阅读&#xff0c;可见程序员们对一个话题的敏感度有多高。 1、麻省理工“只能发500英里的邮件” …
暂无图片
编程学习 ·

redis的下载与安装

下载redis wget http://download.redis.io/releases/redis-5.0.0.tar.gz解压redis tar -zxvf redis-5.0.0.tar.gz编译 make安装 make install快链方便进入redis ln -s redis-5.0.0 redis
暂无图片
编程学习 ·

《大话数据结构》第三章学习笔记--线性表(一)

线性表的定义 线性表&#xff1a;零个或多个数据元素的有限序列。 线性表元素的个数n定义为线性表的长度。n为0时&#xff0c;为空表。 在比较复杂的线性表中&#xff0c;一个数据元素可以由若干个数据项组成。 线性表的存储结构 顺序存储结构 可以用C语言中的一维数组来…
暂无图片
编程学习 ·

对象的扩展

文章目录对象的扩展属性的简洁表示法属性名表达式方法的name属性属性的可枚举性和遍历可枚举性属性的遍历super关键字对象的扩展运算符解构赋值扩展运算符AggregateError错误对象对象的扩展 属性的简洁表示法 const foo bar; const baz {foo}; baz // {foo: "bar"…
暂无图片
编程学习 ·

让程序员最头疼的5种编程语言

世界上的编程语言&#xff0c;按照其应用领域&#xff0c;可以粗略地分成三类。 有的语言是多面手&#xff0c;在很多不同的领域都能派上用场。大家学过的编程语言很多都属于这一类&#xff0c;比如说 C&#xff0c;Java&#xff0c; Python。 有的语言专注于某一特定的领域&…
暂无图片
编程学习 ·

写论文注意事项

参考链接 给研究生修改了一篇论文后&#xff0c;该985博导几近崩溃…… 重点分析 摘要与结论几乎重合 这一条是我见过研究生论文中最常出现的事情&#xff0c;很多情况下&#xff0c;他们论文中摘要部分与结论部分重复率超过70%。对于摘要而言&#xff0c;首先要用一小句话引…
暂无图片
编程学习 ·

安卓 串口开发

上图&#xff1a; 上码&#xff1a; 在APP grable添加 // 串口 需要配合在项目build.gradle中的repositories添加 maven {url "https://jitpack.io" }implementation com.github.licheedev.Android-SerialPort-API:serialport:1.0.1implementation com.jakewhart…
暂无图片
编程学习 ·

2021-2027年中国铪市场调研与发展趋势分析报告

2021-2027年中国铪市场调研与发展趋势分析报告 本报告研究中国市场铪的生产、消费及进出口情况&#xff0c;重点关注在中国市场扮演重要角色的全球及本土铪生产商&#xff0c;呈现这些厂商在中国市场的铪销量、收入、价格、毛利率、市场份额等关键指标。此外&#xff0c;针对…
暂无图片
编程学习 ·

Aggressive cows题目翻译

描述&#xff1a; Farmer John has built a new long barn, with N (2 < N < 100,000) stalls.&#xff08;John农民已经新建了一个长畜棚带有N&#xff08;2<N<100000&#xff09;个牛棚&#xff09; The stalls are located along a straight line at positions…
暂无图片
编程学习 ·

剖析组建PMO的6个大坑︱PMO深度实践

随着事业环境因素的不断纷繁演进&#xff0c;项目时代正在悄悄来临。设立项目经理转岗、要求PMP等项目管理证书已是基操&#xff0c;越来越多的组织开始组建PMO团队&#xff0c;大有曾经公司纷纷建造中台的气质&#xff08;当然两者的本质并不相同&#xff0c;只是说明这个趋势…
暂无图片
编程学习 ·

Flowable入门系列文章118 - 进程实例 07

1、获取流程实例的变量 GET运行时/进程实例/ {processInstanceId} /变量/ {变量名} 表1.获取流程实例的变量 - URL参数 参数需要值描述processInstanceId是串将流程实例的id添加到变量中。变量名是串要获取的变量的名称。 表2.获取流程实例的变量 - 响应代码 响应码描述200指…
暂无图片
编程学习 ·

微信每天自动给女[男]朋友发早安和土味情话

微信通知&#xff0c;每天给女朋友发早安、情话、诗句、天气信息等~ 前言 之前逛GitHub的时候发现了一个自动签到的小工具&#xff0c;b站、掘金等都可以&#xff0c;我看了下源码发现也是很简洁&#xff0c;也尝试用了一下&#xff0c;配置也都很简单&#xff0c;主要是他有一…
暂无图片
编程学习 ·

C语言二分查找详解

二分查找是一种知名度很高的查找算法&#xff0c;在对有序数列进行查找时效率远高于传统的顺序查找。 下面这张动图对比了二者的效率差距。 二分查找的基本思想就是通过把目标数和当前数列的中间数进行比较&#xff0c;从而确定目标数是在中间数的左边还是右边&#xff0c;将查…
暂无图片
编程学习 ·

项目经理,你有什么优势吗?

大侠被一个问题问住了&#xff1a;你和别人比&#xff0c;你的优势是什么呢? 大侠听到这个问题后&#xff0c;脱口而出道&#xff1a;“项目管理能力和经验啊。” 听者抬头看了一下大侠&#xff0c;显然听者对大侠的这个回答不是很满意&#xff0c;但也没有继续追问。 大侠回家…
暂无图片
编程学习 ·

nginx的负载均衡和故障转移

#注&#xff1a;proxy_temp_path和proxy_cache_path指定的路径必须在同一分区 proxy_temp_path /data0/proxy_temp_dir; #设置Web缓存区名称为cache_one&#xff0c;内存缓存空间大小为200MB&#xff0c;1天没有被访问的内容自动清除&#xff0c;硬盘缓存空间大小为30GB。 pro…
暂无图片
编程学习 ·

业务逻辑漏洞

身份认证安全 绕过身份认证的几种方法 暴力破解 测试方法∶在没有验证码限制或者一次验证码可以多次使用的地方&#xff0c;可以分为以下几种情况︰ (1)爆破用户名。当输入的用户名不存在时&#xff0c;会显示请输入正确用户名&#xff0c;或者用户名不存在 (2)已知用户名。…