警惕 JDK8 UDP 和 Thread.interrupt 的 Bug

Posted 2022-12-26 程序员的店小二

背景

线上业务在热点流量大的情况下（业务采用 Java 编程语言实现），单机偶发出现 Hystrix 熔断，接口无法提供服务。如下图所示：

Hystrix circuit short-circuited and is OPEN# 代表Hystrix在一个窗口时间内失败了N次，发生短路。短路时间默认为 5 秒，5秒之内拒绝所有的请求，之后开始运行。

统计了一下 1 个小时内居然有 5 万多条。

最初怀疑依赖下游的某个 RPC 接口出现问题。但从监控来看，异常时间点多个 RPC 接口异常率都有所上升。所以考虑是自身单机存在什么问题，导致调用依赖的 RPC 接口失败，产生了大量的熔断。

这里还有很重要的一点：在单机出现问题第一时间，摘掉了流量，过半小时后恢复流量，依旧熔断无法恢复。

若摘掉流量后，静置一段时间放开流量服务恢复，证明可能是由于流量过载导致的问题，如 JVM 内存不够，GC 回收不过来，频繁 GC。这样的话流量掐掉后，GC 一段时间后内存够用，服务恢复正常。

若摘掉流量后，静置一段时间放开流量服务依旧熔断。在单机出现问题的场景下，很可能是 JVM 内部的问题（包括应用自身问题或者 JVM 的一些问题，如死锁）。

排查

通常排查这种自身问题可从几个方面入手：

• CPU Load、使用率、内存使用率是否过高；

• 网卡出入速率是否有抖动，包括 TCP 重传；

• 磁盘 IOPS 是否过高，导致一些 sys call 阻塞；

• JVM 是否出现 STW 动作，包括不限于 GC、JIT 等；

• 是否有 OOM、StackOverflow、死锁等现象；

• 代码出现 Bug；

• 虚拟化对应用进行 STW 动作。

根据这些逐一分析。

1. 监控CPU和内存如下图所示

CPU 有明显的抖动，内存使用率正常（18:30 断崖式下滑是对服务进行了上线，可忽略不管）。注意：问题发生在 19:00 以后。可以看到 CPU 在出问题时间段内有明显的波动。

2. 查看监控网卡如下图所示

在 19:00 之后出问题的时间段网卡出入速率略有波动，可忽略。

3. 查看磁盘 IOS 如下图所示

磁盘 IOPS 虽然比较高，但 19:00 前后都比较平均。

4. 查看 gclog 如下图所示

虽然 Young GC 比较频繁，但回收的比例还是比较大，耗时也不高。没有明显的其他原因导致 STW 占用时间长的迹象。

5. 打印线程栈如下图所示

jstack 打出的线程栈就很明显了，最下面直接显示了死锁！

6. Review了最近上线的代码，改动很小没有问题。

7. 由于打印线程栈出现死锁，问题很明显，不用排查虚拟化了。

问题很明显了，JVM 出现了死锁，导致 Hystirx 熔断。
从死锁的日志来看，似乎跟 DNS 相关。难道 Java 的 DNS 有啥 Bug？

分析

在死锁线程栈中很明显地标记出了 pool-486-thread-132 在等 0x00000006b77f2098 这把锁，并且这把锁被 hstirx-*** 线程持有着。同时 hstirx-*** 在等待 0x00000006b77f2128 这把锁，并且这把锁被 pool-486-thread-132 线程持有着。

这俩个线程栈中同时出现了 DNS 和 DatagramChannel 相关的类，证明死锁很大一部分原因是由 DNS 在发 UDP 包的情况下产生了死锁。我们知道死锁是俩个线程对相同临界区资源竞争时，加锁不当产生的。复习下死锁的四个必要条件：

• 互斥条件：进程要求对所分配的资源进行排它性控制，即在一段时间内某资源仅为一进程所占用；

• 请求和保持条件：当进程因请求资源而阻塞时，对已获得的资源保持不放；

• 不剥夺条件：进程已获得的资源在未使用完之前，不能剥夺，只能在使用完时由自己释放；

• 环路等待条件：在发生死锁时，必然存在一个进程–资源的环形链。

那我们使用的 DNS 为啥会出现这样的问题？难道是 JDK 或者是 dnsjava（我们使用了dnsjava）的 Bug？

排查 Bug 的最好方法就是阅读源码，我们可以通过死锁的线程栈自底向上逐层跟踪代码。

先看 histirx-*** 的死锁线程栈 ：

1. 从业务调用点开始，这里我们的业务向 BatchExecutor（公司内部封装的线程池操作）提交了线程。

2. 本质上调用 AbstractExecutorService.invokeAll 方法，该方法在线程池中的线程执行结束时，finally 会触发 FutureTask.cancel 方法。

3. 由于在调用 cancel 方法对 mayInterruptIfRunning 实参传递的是 true，所以会执行 Thread.interrupt 方法。

4. Thread.interrupt 会对 blockerlock 加锁，根据线程栈，我们看到 intterupt 后会执行 DatagramChannelImpl.implCloseSelectableChannel 方法关闭 UDP 链接。

5. 而 implCloseSelectableChannel 方法要拿到 stateLock 的锁，根据线程栈，此时出现锁等待。

再看 pool-486-thread-132 的死锁线程栈：

1. 这个线程栈比较长，直接从 at org.xbill.DNS.UDPClient.connect(UDPClient.java:107) 开始看。可以从包名看出，这是做 dnsjava 向 DNS server 发起 UDP 请求。

2. connect 方法 通过 DatagramChannel.connect 开启 UDP 连接。

3. DatagramChannel.connect中会锁住readLock、writeLock、stateLock，即线程栈中的：

• readLock locked <0x00000006b77f20f8> (a java.lang.Object)

• writeLock locked <0x00000006b77f2110> (a java.lang.Object)

• stateLock locked <0x00000006b77f2128> (a java.lang.Object)

并锁住 bloackingLock 即线程栈中的 locked <0x00000006b77f20e0> (a java.lang.Object)，然后分配 Buffer 并执行 receive 方法。

在 receive 方法并根据线程栈逐层往下，recevie 方法 finally 最后会执行 end 方法。end 方法调用到最后实际上调用了 Thread.blockedOn，bockedOn 需要拿到 blockerLock 锁。此时这个锁 <0x00000006b77f2098> 正在被 histirx-*** 线程持有着。

这个链路看起来，似乎是由一个线程建立 UDP 并发包，一个线程对该线程进行 interrupt，就会产生死锁。

这一点，也有人在 OpenJDK 的 Bug 列表中提出， JDK-8228765。

那么线上为啥会出现 hystrix 线程对另外一个 HTTP 请求正在 DNS 解析线程进行 interrupt 的动作？

这里简单说明下：我们的业务中会通过 BatchExecutor 提交一个异步的业务逻辑，并且超时时间为 300ms。若 300ms 以后未正常返回结果，自然会执行 finally。

由于在异步业务逻辑比较复杂，请求多个 RPC 或其他资源时，若一个请求超过 300ms，其他业务逻辑也会被超时终止，即被 interrupt。当有 DNS 时，便会触发这个 Bug。业务流量大的情况下触发概率比较大。

复现

经过上面的分析并参考 JDK-8228765，我们可以构造 2 个线程，一个发 UDP 包，一个对其进行 interrupt 操作，参考如下代码：

import java.io.IOException;import java.net.InetSocketAddress;import java.net.StandardSocketOptions;import java.nio.channels.DatagramChannel;import java.util.concurrent.ThreadLocalRandom;
public class UDPReceiver 
    public static void main(String[] args) throws IOException, InterruptedException         DatagramChannel receiver = DatagramChannel.open();        receiver.setOption(StandardSocketOptions.SO_REUSEADDR, true);        receiver.bind(new InetSocketAddress("localhost",8000));//监听UDP 8000端口
        UDPSender sender = new UDPSender();        new Thread(sender).start(); //启动一个线程开始发UDP包        while (true)             System.out.println("before interrupt");            sender.interruptThis(); //这里会触发死锁            System.out.println("after interrupt");            Thread.sleep(ThreadLocalRandom.current().nextLong(0,100));            ​​​​

import java.net.InetSocketAddress;import java.net.StandardSocketOptions;import java.nio.ByteBuffer;import java.nio.channels.DatagramChannel;import java.util.concurrent.ThreadLocalRandom;
public class UDPSender implements Runnable     private static final InetSocketAddress target = new InetSocketAddress("localhost", 8000);    private Thread thisThread;

    public void interruptThis()         if (null != thisThread)             thisThread.interrupt(); //引发死锁的源头2            
    @Override    public void run()         thisThread = Thread.currentThread(); //保存一下sender的当前线程        while (true)             try                 DatagramChannel sender = DatagramChannel.open();                sender.setOption(StandardSocketOptions.SO_REUSEADDR, true);                sender.connect(target); //连接本地8000端口发包                System.out.println("sending...");                sender.send(ByteBuffer.allocate(100).putInt(1), target);//引发死锁的源头1                System.out.println("sending success...");                Thread.sleep(ThreadLocalRandom.current().nextLong(0, 100));             catch (Exception e)                         
            

如下图所示，在跑几轮后 before interrupt 的时候出现死锁。

打印线程栈，最后可看到死锁信息。

jstack -l <pid>

线程 Thread-0 等待的锁对象 0x000000076b0f9668 由主线程在执行 UDPSender.interruptThis 时锁住，即对 Thread-0 线程进行 interrupt。根据 Thread.interrupt 方法的描述，若当前线程处于 IO 方法阻塞时，通道会被关闭，会抛出 ClosedByInterruptException 异常并设置中断状态为 true。

死锁的整个过程如下：先看 new Thread(sender).start() 即 Thread-0 的执行。
可以看死锁的线程栈调用链路执行情况，参考代码推导：

1. DatagramChannelImp l实现了AbstractInterruptibleChannel。在DatagramChannelImpl.send 方法中会拿到两把锁，注意其中一把为 stateLock，即线程中的 - locked <0x000000076b1e2be8> (a java.lang.Object)。

2. 在 write 方法中，可以看到调用 this.begin 方法，即 AbstracInterruptibleChannel.begin。在 IOUtil.write 真正发包完成后，会执行 finally 中的 this.end 方法。

AbstracInterruptibleChannel.begin 注册了收到 interrupt 后要执行的逻辑，注意这里，下面会用。

3. 在 AbstractInterruptibleChannel.end 方法中通过 blockedOn 方法标记 block 状态。

4. blockedOn 会最终调到 Thread.blockedOn 方法，且实参为当前 Thread-0 线程。注意这里，要拿到 blockerlock，即线程栈中的 - waiting to lock <0x000000076b0f9668> (a java.lang.Object)。

再看 sender.interruptThis() 的执行：可以看死锁的线程栈调用链路执行情况，参考代码推导。

1. 在 Thread.interrupt 方法中会调用 b.interrupt，注意这里会拿到 blokcerLock，即线程栈中的 - locked <0x000000076b0f9668> (a java.lang.Object)。

2. b.interrupt 会触发 AbstracInterruptibleChannel 在 begin 方法中实现的 interrupt 方法。

3. 通过 AbstracInterruptibleChannel.implCloseChannel 关闭通道。

4. 在 DatagramChannelImpl.implCloseChannel 的实现中，要拿到 stateLock 这把锁。注意这里就是线程栈中的 - waiting to lock <0x000000076b1e2be8> (a java.lang.Object)。

从上面的分析可以很明显的看出，主线程触发 Thread-0 的 interrupt 动作时，在执行 interupt 方法持有了 blockerLock 锁。关闭通道要拿 stateLock 锁，而 Thread-0 在发包时先拿到了 stateLock 锁，并且设置 block 状态时要拿 blockerLock 锁，此时出现死锁！

解决方法

根据 OpenJDK 的 Bug 列表中的说明 JDK-8228765 ，这个 Bug 从 JDK-8039509 就开始有了，一直到 JDK13 才修复。所以，要么升级 JDK 到 13，要么死！我选择了死。

我们项目中使用了 dnsjava，在 dnsjava的 Github上 issues#69 里也是有报这个 Bug的。另外在 logstash 中也有类似的问题 issues#117。

当然如果选择了死，那就是遇到了重启服务器了。

总结

JVM 的 Bug 也很多，同时也很诡异，需要 仔细观察运行时状态 + 阅读源码 才能分析出原因，如果你不想分析原因，可以用 Google 搜搜看，很可能已经有了答案。

排查问题思路很重要，由于业务环境通常比较复杂，在大流量、大数据量的情况下会有各种千奇百怪的问题，需要有足够的耐心和较广的知识面。

转自：bd7xzz，

链接：blog.csdn.net/kid_2412/article/details/128125053