关于后端:刺激线程池的一个BUG直接把CPU干到100了

57次阅读

共计 6518 个字符,预计需要花费 17 分钟才能阅读完成。

你好呀,我是歪歪。

给大家分享一个对于 ScheduledExecutorService 线程池的 BUG 啊,这个 BUG 能间接把 CPU 给飚到 100%,心愿大家永远踩不到。

然而,u1s1,一般来说也很难踩到。

到底咋回事呢,让我给你细细嗦嗦。

Demo

老规矩,依照常规,先搞个 Demo 进去玩玩:

我的项目外面应用到了 ScheduledThreadPoolExecutor 线程池,该线程池对应的外围线程数放在配置文件外面,通过 @Value 注解来读取配置文件。

而后通过接口触发这个线程池外面的工作。

具体来说就是在下面的示例代码中,在调用 testScheduledPool 接口之后,程序会在 60 秒之后输入“执行业务逻辑”。

这个代码的逻辑还是非常简单清晰的,然而下面的代码有一个问题,不晓得你看进去没有?

没看进去也没关系,我这里都是激励式教学的,不打击同学的积极性。

所以,别着急,我先给你跑起来,你瞅一眼立马就能看出问题是啥:

为什么 coreSize 是 0 呢,咱们配置文件外面明明写的是 2 啊?

因为 setCoreSize 办法是 static 的,导致 @Value 注解生效。

如果去掉 static 那么就能正确读取到配置文件中的配置:

尽管这外面也大有学识,然而这并不是本文的重点,这只是一个引子,

为的是引出为什么会在我的项目外面呈现上面这种 coreSize 等于 0 的奇怪的代码:

ScheduledExecutorService executor = Executors.newScheduledThreadPool(0);

如果我间接给出下面的代码,一点有人说只有小(大)可(傻)爱(逼)才会这样写。

然而铺垫一个背景之后,就容易接受的多了。

你永远能够置信我的行文构造,老司开车稳得很,你释怀。

好,通过后面的铺垫,其实咱们的 Demo 能间接简化到这个样子:

public static void main(String[] args){ScheduledExecutorService e = Executors.newScheduledThreadPool(0);
    e.schedule(() -> {System.out.println("业务逻辑");
    }, 60, TimeUnit.SECONDS);
    e.shutdown();}

这个代码是能够失常运行的,你粘过来间接就能跑,60 秒后是会失常输入的。

如果你感觉 60 秒太长了,那么你能够改成 3 秒运行一下,看看程序是不是失常运行并完结了。

然而就这个看起来问题不大的代码,会导致 CPU 飚到 100% 去。

真的,儿豁嘛。

咋回事呢

到底咋回事呢?

这个其实就是 JDK 的 BUG 导致的,我带你瞅瞅:

https://bugs.openjdk.org/brow…

首先,你看 Fix Version 那个中央是 9,也就是说明这个 BUG 是在 JDK 9 外面修复了。JDK 8 外面是能够复现的。

其次,这个题目其实就蕴含了十分多的信息了,它说对于 ScheduledExecutorService 来说 getTask 办法外面存在频繁的循环。

那么问题就来了:频繁的循环,比方 for(;;),while(true) 这样的代码,长时间从循环外面走不进去,会导致什么景象?

那不就是导致 CPU 飙高吗。

留神,这里我说的是“长时间从循环外面走不进去”,而不是死循环,这两者之间的差别还是很大的。

我代码外面的示例就是应用的提出 BUG 的哥们给出的实例:

他说,在这个示例下,如果你在一个只有单核的服务器上跑,而后应用 TOP 命令,会看到继续 60 秒的 CPU 使用率为 100%。

为什么呢?

答案就藏在后面提到的 getTask 办法中:

java.util.concurrent.ThreadPoolExecutor#getTask

这个办法外面果然是有一个相似于无线循环的代码,然而它为什么不停的执行呢?

当初连忙想一想线程池的根本运行原理。当没有工作解决的时候,外围线程在干啥?

是不是就阻塞在这个中央,等着工作过去进行解决的,这个能了解吧:

那我再问你一个问题,这行代码的作用是干啥:

workQueue.poll(keepAliveTime, TimeUnit.NANOSECONDS)

是不是在指定工夫内如果没有从队列外面拉取到工作,则抛出 InterruptedException。

那么它什么时候会被触发呢?

在 timed 参数为 true 的时候。

timed 参数什么时候会为 true 呢?

当 allowCoreThreadTimeOut 为 true 或者当前工作的线程大于外围线程数的时候。

而 allowCoreThreadTimeOut 默认为 false:

那么也就是在这个案例下满足了当前工作的线程大于外围线程数这个条件:

wc > corePoolSize

通过 Debug 晓得,wc 是 1,corePoolSize 为 0:

所以 timed 变成了 true。

好,这里要留神了,敌人。

通过后面的剖析,咱们曾经晓得了在以后的案例下,会触发 for(;;) 这个逻辑:

workQueue.poll(keepAliveTime, TimeUnit.NANOSECONDS)

那么这个 keepAliveTime 到底是多少呢?

来,大声的喊出这个数字:0,这是一个意想不到的、阴谋诡计的 0。

所以,这个中央中的 r 每次都会返回一个 null,而后再次开启循环。

对于失常的线程池来说,触发了这个逻辑,代表没有工作要执行了,能够把对应线程进行回收了。

回收,对应的就是这部分代码会返回一个 null:

而后在里面 runWorker 办法中的,因为 getTask 返回了 null,从而执行了 finally 代码外面的逻辑,也就是从以后线程池移除线程的逻辑:

然而,敌人,我要说然而了。

在咱们的案例下,你看 if 判断的条件:

.jpg)

这外面的 wc > 1 || workQueue.isEmpty()) 是 false

所以这个 if 条件不成立,那么它又走到了 poll 这里:

workQueue.poll(keepAliveTime, TimeUnit.NANOSECONDS)

因为这里的 keepAliveTime 是 0,所以快马加鞭的的开启下一轮循环。

那么这个循环什么时候完结呢?

就是在从队列外面获取到工作的时候。

那么队列外面什么时候才会有工作呢?

在咱们的案例外面,是 60 秒之后。

所以,在这 60 秒内,这部分代码相当于是一个“死循环”,导致 CPU 继续飙高到 100%。

这就是 BUG,这就是根本原因。

然而看到这里是不是感觉还差点意思?

我说 100% 就 100% 吗?

得拿出石锤来才行啊。

所以,为了拿出实锤,眼见为实,我把外围流程拿进去,而后略微改变一点点代码:

public static void main(String[] args) {
    ArrayBlockingQueue<Runnable> workQueue =
            new ArrayBlockingQueue<>(100);
    // 绑定到 5 号 CPU 上执行
    try (AffinityLock affinityLock = AffinityLock.acquireLock(5)) {for (; ;) {
            try {Runnable r = workQueue.poll(0, TimeUnit.NANOSECONDS);
                if (r != null)
                    break;
            } catch (InterruptedException retry) {}}
    }
}

AffinityLock 这个类在之前的文章外面呈现过:《面试官:Java 如何绑定线程到指定 CPU 上执行?》

就是把线程绑定到指定 CPU 下来执行,缩小 CPU 抖动带来的损耗,
具体我就不介绍了,有趣味去看我之前的文章。

把这个程序跑起来之后,关上资源监视器,你能够看到 5 号 CPU 立马就飚到 100% 了,进行运行之后,立马就下来了:

这就是眼见为实,这真是 JDK 的 BUG,我真没骗你。

怎么修复

在 JDK 9 外面是怎么修复这个 BUG 的呢?

在后面提到的 BUG 的链接中,有这样的一个链接,外面就是 JDK 9 版本外面针对上述的 BUG 进行的修复:

http://hg.openjdk.java.net/jd…

点开这个链接之后,你能够找到这个中央:

首先比照一下标号为 ① 和 ② 的中央,默认值从 0 纳秒批改为了 DEFAULT_KEEPALIVE_MILLIS 毫秒。

而 DEFAULT_KEEPALIVE_MILLIS 的值为在标号为 ③ 的中央,10L。

也就是默认从 0 纳秒批改为了 10 毫秒。而这一处的改变,就是为了防止出现 coreSize 为 0 的状况。

咱们重点关注一下 DEFAULT_KEEPALIVE_MILLIS 下面的那一坨正文。

我给你翻译一下,大略是这样的:

这个值呢一般来说是用不上的,因为在 ScheduledThreadPoolExecutor 线程池外面的线程都是外围线程。

然而,如果用户创立的线程池的时候,不听劝,头铁,要把 corePoolSize 设置为 0 会产生什么呢?

因为 keepAlive 参数设置的为 0,那么就会导致线程在 getTask 办法外面十分频繁的循环,从而导致 CPU 飙高。

那怎么办呢?

很简略,设置一个小而非零的值就能够,而这个小是绝对于 JVM 的运行工夫而言的。

所以这个 10 毫秒就是这样来的。

再来一个

在钻研后面提到的编号为 8065320 的 BUG 的时候,我还发现一个意外播种,编号为 8051859 的 BUG,它们是挨着的,排排坐。

有点意思,也很简略,所以分享一波:

https://bugs.openjdk.org/brow…

这个 BUG 又说的是啥事儿呢:

看截图这个 BUG 也是在 JDK 9 版本之后修复的。

这个 BUG 的题目说的是 ScheduledExecutorService 线程池的 scheduleWithFixedDelay 办法,遇到大提早时会执行失败。

具体啥意思呢?

咱们还是先拿着 Demo 说:

public class ScheduledTaskBug {static public void main(String[] args) throws InterruptedException {ScheduledExecutorService executor = Executors.newSingleThreadScheduledExecutor();
        // 第一个工作
        executor.scheduleWithFixedDelay(new Runnable() {
            @Override
            public void run() {System.out.println("running scheduled task with delay:" + new Date());
            }
        }, 0, Long.MAX_VALUE, TimeUnit.MICROSECONDS);

        // 第二个工作
        executor.submit(new Runnable() {
            @Override
            public void run() {System.out.println("running immediate task:" + new Date());
            }
        });
        Thread.sleep(5000);
        executor.shutdownNow();}
}

你把这个代码粘过来之后,发现输入是这样的:

只有第一个工作执行了,第二个工作没有输入后果。

失常来说,第一个工作的延迟时间,也就是 initialDelay 参数是 0,所以第一次执行的时候是立刻执行:

比方我改成这样,把周期执行的工夫单位,由微秒批改为纳秒,就失常了:

神奇不神奇?你说这不是 BUG 这是啥?

提出 BUG 的这个哥们在形容外面介绍了 BUG 的起因,次要是提到了一个字段和两个办法:

一个字段是指 period,两个办法别离是 TimeUnit.toNanos(-delay) 和 ScheduledFutureTask.setNextRunTime()。

首先,在 ScheduledThreadPoolExecutor 外面 period 字段有三个取值范畴:

  • 负数,代表的是依照固定速率执行 (scheduleAtFixedRate)。
  • 正数,代表的是依照固定延时执行 (scheduleWithFixedDelay)。
  • 0,代表的是非重复性工作。

比方咱们的示例代码中调用的是 scheduleWithFixedDelay 办法,它外面就会在调用 TimeUnit.toNanos 办法的时候取反,让 period 字段为正数:

好,此时咱们开始 Debug 咱们的 Demo,先来一个失常的。

比方咱们来一个每 30ms 执行一次的周期工作,请认真看:

在执行 TimeUnit.toNanos(-delay) 这一行代码的时候,把 30 微秒转化为了 -30000 纳秒,也就是把 period 设置为 -30000。

而后来到 setNextRunTime 办法的时候,计算工作下一次触发工夫的时候,又把 period 转为负数,没有任何故障:

然而,当咱们把 30 批改为 Long.MAX_VALUE 的时候,有意思的事件就呈现了:

delay=9223372036854775807
-delay=-9223372036854775807
unit.toNanos(-delay)=-9223372036854775808

间接给干溢出了,变成了 Long.MIN_VALUE:

当来到 setNextRunTime 办法的时候,你会发现因为咱们的 p 曾经是 Long.MIN_VALUE 了。

那么 -p 是多少呢?

给你跑一下:

Long.MIN_VALUE 的绝对值,还是 Long.MIN_VALUE。一个神奇的小知识点送给你,不客气。

所以 -p 还是 Long.MIN_VALUE:

咱们来算一下啊,一秒等于 10 亿纳秒:

那么下一次触发工夫就变成了这样:

292 年之前。

这就是在 BUG 形容中提到的:

This results in triggerTime returning a time in the distant past.

the distant past,就是 long long ago,就是 292 年之前。就是 1731 年,雍正九年,那个时候的皇帝还是九子夺嫡中一顿乱杀,冲出重围的胤禛大佬。

的确是很久很久以前了。

那么这个 BUG 怎么修复呢?

其实很简略:

把 unit.toNanos(-delay) 批改为 -unit.toNanos(delay),搞定。

我给你盘一下:

这样就不会溢出,工夫就变成了 292 年之后。

那么问题就来了,谁特么会设置一个每 292 年执行一次的 Java 定时工作呢?

好,你看到这里了,本文就算完结了,我来问你一个问题:你晓得了这两个 BUG 之后,对你来说有什么播种吗?

没有,是的,除了节约了几分钟工夫外,没有任何播种。

那么祝贺你,又在我这里学到了两个没有卵用的知识点。

汇总

这个大节为什么叫做汇总呢?

因为我发现这里呈现的一串 BUG,除了本文提到的 2 个外,还有 3 个我都写过了,所以在这里汇个总,充点字数,凑个篇幅:

8054446: Repeated offer and remove on ConcurrentLinkedQueue lead to an OutOfMemoryError

《我的程序跑了 60 多小时,就是为了让你看一眼 JDK 的 BUG 导致的内存透露。》

这篇文章就是从 ConcurrentLinkedQueue 队列的一个 BUG 讲起。jetty 框架外面的线程池用到了这个队列,导致了内存透露。

同时通过 jconsole、VisualVM、jmc 这三个可视化监控工具,让你看见“内存透露”的产生。

8062841: ConcurrentHashMap.computeIfAbsent stuck in an endless loop

《震惊!ConcurrentHashMap 外面也有死循环,作者留下的“彩蛋”理解一下?》

这个 BUG 在 Dubbo 和 Seata 外面都有提到过,也被 Seata 官网的一篇博客中被援用过:

https://seata.io/zh-cn/blog/s…

8073704: FutureTask.isDone returns true when task has not yet completed

《Doug Lea 在 J.U.C 包外面写的 BUG 又被网友发现了。》

这个 BUG 也是在 JDK 9 版本外面修复的,逻辑弯弯绕绕的,然而了解之后,对于 FutureTask 状态流转就能有一个比拟粗浅的认知了。有趣味能够看看。

正文完
 0