Java21虚拟线程-锁在哪里呢？ ::

原文链接⌗

Java 21 Virtual Threads - Dude, Where’s My Lock?

这篇文章是关于Java21的虚拟线程的，主要讨论了一个关于虚拟线程的故障案例。

问题⌗

Netflix接到了jvm间歇性超时，实例被挂起的问题报告。这些报告的共同点是都是运行着java21的spring boot 3应用，且都使用嵌入式的tomcat来提供服务。这些jvm虽然仍然在运行，但是确无法提供服务。

Netflix内部应该还有java17的技术栈服务，所以可以将以上信息作为问题的公共特征抽取出来。

它们的metrics检测到closewait状态的socket数量持续增加。

排查⌗

收集信息⌗

closewait造成的原因是连接的对端关闭了连接，但是本地还未关闭，还在等待关闭。者通常意味着本地线程可能因为某种原因挂起了。所以他们先要排查了thread dump。

Netflix的服务有定期保存thread dump数据

他们在告警系统中找到一个这类被挂起的实例，并查看对应的thread dump数据。从这些数据，只能看出该jvm处于空闲状态，并没有特别的活动。

他们查看了这些服务的最近变更，发现它们都启用了virtual threads特性。而virutal thread的调用栈并不会出现在jstack生成的thread dump中。

Neflix内部服务启用virtual thread特性应该也是分阶段的，应该还有许多服务未启用该特性。

为了获取包含virtual thread状态的完整thread dump，他们使用了jcmd Thread.dump_to_file命令。

为了查看jvm内部的完整状态，他们对该实例也收集了heap dump。

分析⌗

他们从thread dump信息中看到了成千上万的空虚拟线程。

#119821 "" virtual
#119820 "" virtual
#119823 "" virtual
#120847 "" virtual
#119822 "" virtual
...

这些虚拟线程被创建出来，但是尚未开始执行，所以stack trace信息。且这些空虚拟线程的数量大致等于处于closewait状态的socket数量。

虚拟线程在遇到阻塞的时候，会让出占据的系统线程，并保留在内存中，等待恢复执行。Jvm会将该空闲出来的系统线程分配给其他的虚拟线程，从而充分利用cpu资源。所以多个虚拟线程可以复用同一个系统线程。

在JVM术语中，该系统线程被称为carrier thread。虚拟线程在执行的时候，被它mounted，在等待的时候被unmounted。 JEP 444

JVM会维护一个系统线程(carrier thread)池，通过一个fork join pool来创建和管理虚拟线程。默认情况下,这个线程池中的carrrier thread的数量和cpu核心数量相同。

在Netflix中，他们原先使用tomcat的blocking model。也就是每个请求都会有一个专门的工作线程来处理，该工作线程直到返回response才会被释放。在启用虚拟线程之后，tomcat的VirtualThreadExecutor会对每个请求都创建一个虚拟线程。

根据前面的现象，可以推断tomcat创建虚拟线程之后，并没有执行该虚拟线程。

为什么Tomcat没有执行这些虚拟线程⌗

在oracle的虚拟线程说明中有这么一段

A virtual thread cannot be unmounted during blocking operations when it is pinned to its carrier. A virtual thread is pinned in the following situations:

The virtual thread runs code inside a synchronized block or method

The virtual thread runs a native method or a foreign function (see Foreign Function and > Memory API)

也就是在synchronized块中的时候，一个虚拟线程会被固定(pin)到系统线程上。

他们获取的thread dump信息如下：

#119515 "" virtual
      java.base/jdk.internal.misc.Unsafe.park(Native Method)
      java.base/java.lang.VirtualThread.parkOnCarrierThread(VirtualThread.java:661)
      java.base/java.lang.VirtualThread.park(VirtualThread.java:593)
      java.base/java.lang.System$2.parkVirtualThread(System.java:2643)
      java.base/jdk.internal.misc.VirtualThreads.park(VirtualThreads.java:54)
      java.base/java.util.concurrent.locks.LockSupport.park(LockSupport.java:219)
      java.base/java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:754)
      java.base/java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:990)
      java.base/java.util.concurrent.locks.ReentrantLock$Sync.lock(ReentrantLock.java:153)
      java.base/java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:322)
      zipkin2.reporter.internal.CountBoundedQueue.offer(CountBoundedQueue.java:54)
      zipkin2.reporter.internal.AsyncReporter$BoundedAsyncReporter.report(AsyncReporter.java:230)
      zipkin2.reporter.brave.AsyncZipkinSpanHandler.end(AsyncZipkinSpanHandler.java:214)
      brave.internal.handler.NoopAwareSpanHandler$CompositeSpanHandler.end(NoopAwareSpanHandler.java:98)
      brave.internal.handler.NoopAwareSpanHandler.end(NoopAwareSpanHandler.java:48)
      brave.internal.recorder.PendingSpans.finish(PendingSpans.java:116)
      brave.RealSpan.finish(RealSpan.java:134)
      brave.RealSpan.finish(RealSpan.java:129)
      io.micrometer.tracing.brave.bridge.BraveSpan.end(BraveSpan.java:117)
      io.micrometer.tracing.annotation.AbstractMethodInvocationProcessor.after(AbstractMethodInvocationProcessor.java:67)
      io.micrometer.tracing.annotation.ImperativeMethodInvocationProcessor.proceedUnderSynchronousSpan(ImperativeMethodInvocationProcessor.java:98)
      io.micrometer.tracing.annotation.ImperativeMethodInvocationProcessor.process(ImperativeMethodInvocationProcessor.java:73)
      io.micrometer.tracing.annotation.SpanAspect.newSpanMethod(SpanAspect.java:59)
      java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:103)
      java.base/java.lang.reflect.Method.invoke(Method.java:580)
      org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethodWithGivenArgs(AbstractAspectJAdvice.java:637)
...

从上面的日志，我们可以直到该虚拟线程尝试获取锁java.base/java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:322)，但是没有成功。之后虚拟线程就被阻塞了(park)，等待获取锁。

他们的代码从brave.RealSpan.finish(RealSpan.java:134)开始进入synchronization。

谁持有锁⌗

一般来说thread dump会通过- locked <0x…> (at …)或Locked ownable synchronizers来指示是谁持有锁。但是他们并没有看到相关信息。不论jstack或者jcmd的thread dump信息都没有这些信息。这是java21的一个limitation，会在未来被解决。

他们发现有6个线程在竞争相同的ReentrantLock。他们有4个vCPU，4个线程的日志和上面一样。以下是剩下2个中的一个线程的日志

#119516 "" virtual
      java.base/java.lang.VirtualThread.park(VirtualThread.java:582)
      java.base/java.lang.System$2.parkVirtualThread(System.java:2643)
      java.base/jdk.internal.misc.VirtualThreads.park(VirtualThreads.java:54)
      java.base/java.util.concurrent.locks.LockSupport.park(LockSupport.java:219)
      java.base/java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:754)
      java.base/java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:990)
      java.base/java.util.concurrent.locks.ReentrantLock$Sync.lock(ReentrantLock.java:153)
      java.base/java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:322)
      zipkin2.reporter.internal.CountBoundedQueue.offer(CountBoundedQueue.java:54)
      zipkin2.reporter.internal.AsyncReporter$BoundedAsyncReporter.report(AsyncReporter.java:230)
      zipkin2.reporter.brave.AsyncZipkinSpanHandler.end(AsyncZipkinSpanHandler.java:214)
      brave.internal.handler.NoopAwareSpanHandler$CompositeSpanHandler.end(NoopAwareSpanHandler.java:98)
      brave.internal.handler.NoopAwareSpanHandler.end(NoopAwareSpanHandler.java:48)
      brave.internal.recorder.PendingSpans.finish(PendingSpans.java:116)
      brave.RealScopedSpan.finish(RealScopedSpan.java:64)
      ...

虽然这个日志和其他4个线程很类似，但是没有brave.RealSpan.finish(RealSpan.java:134)。

剩下的第6个线程的日志

#107 "AsyncReporter <redacted>"
      java.base/jdk.internal.misc.Unsafe.park(Native Method)
      java.base/java.util.concurrent.locks.LockSupport.park(LockSupport.java:221)
      java.base/java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:754)
      java.base/java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:1761)
      zipkin2.reporter.internal.CountBoundedQueue.drainTo(CountBoundedQueue.java:81)
      zipkin2.reporter.internal.AsyncReporter$BoundedAsyncReporter.flush(AsyncReporter.java:241)
      zipkin2.reporter.internal.AsyncReporter$Flusher.run(AsyncReporter.java:352)
      java.base/java.lang.Thread.run(Thread.java:1583)

这实际上是一个普通的平台线程，而不是虚拟线程。特别注意这个堆栈跟踪中的行号，线程似乎在完成wait之后卡在了内部的acquire()方法中。也就是说，该调用线程在进入awaitNanos()时持有了锁。然而，当等待结束时，它无法重新获取锁。

表格显示结果

Thread ID/name	Virtual?	“synchronized” block?	Pinned?	Waiting for the lock?
#119513 ""	Yes	Yes	Yes	Yes
#119514 ""	Yes	Yes	Yes	Yes
#119515 ""	Yes	Yes	Yes	Yes
#119517 “<redacted> @DefaultExecutor - 46542”	Yes	Yes	Yes	Yes
#119516 ""	Yes	No	No	Yes
#107 “AsyncReporter ”	No	No	N/A	Yes

有5个虚拟线程和1个普通线程正在等待获取锁。在这5个虚拟线程中，有4个被固定在的系统线程上。我们仍然没有获取到谁持有锁的信息。由于thread dump中没有更多可供我们分析的内容，接下来的逻辑步骤是查看heap dump并检查锁的状态。

检查锁状态⌗

他们使用eclipse mat来分析heap dump。他们检查了AsyncReporter这个非虚拟线程的堆栈对象，以定位锁对象。

heap-dump

exclusiveOwnerThread字段为null(2)，表示没有线程持有锁。
ExclusiveNode（3）为空(waiter为null, status为0)后面紧跟着的另一个ExclusiveNode，它的waiter指向了虚拟线程#119516。
他们发现此处唯一清理exclusiveOwnerThread字段的地方在ReentrantLock.Sync.tryRelease()方法中。

       protected final boolean tryRelease(int releases) {
            int c = getState() - releases;
            if (getExclusiveOwnerThread() != Thread.currentThread())
                throw new IllegalMonitorStateException();
            boolean free = (c == 0);
            if (free)
                setExclusiveOwnerThread(null);
            setState(c);
            return free;
        }

在成功地调用了tryRelease之后，该锁的持有线程尝试向下个waiter发送信号。code

    public final boolean release(int arg) {
        if (tryRelease(arg)) {
            signalNext(head);
            return true;
        }
        return false;
    }

此时锁的持有线程仍然是the head of the list，即便该锁的ownership已经释放掉了。下一个waiter的线程即将尝试去获取该锁。

要理解这里信号发送的流程，需要了解AbstractQueuedSynchronizer.acquire()这个方法。简单来说，就是线程尝试获取锁，如果没有获取，就将自己park。

while(true) {
   if (tryAcquire()) {
      return; // lock acquired
   }
   park();
}

在锁的持有线程释放锁，并发送信号来unpark下一个线程的时候，该unpark的线程执行这个loop，尝试去获取锁。但是从thread dump信息来看，所有的虚拟线程都park在754 行。一旦被唤醒，成功获取锁的线程应该进入此代码块，重置head of the list为自己，并清除对waiter的引用。

但是这里的问题是虚拟线程#119516仍然在等待，和其他的虚拟线程一样。这是为什么呢？

总共有6个线程在等待获取锁，其中4个虚拟线程分别固定在一个操作系统线程上。这4个线程在获取到锁并离开同步块之前不会释放它们的系统线程。
#107 “AsyncReporter <redacted>”是个普通的平台线程，因此在获取锁后，就可以正常执行。
#119516是个虚拟线程，但是并没有固定在系统线程上，因为只有4个vCPU，系统线程已经被以上的4个虚拟线程占满了。所以该虚拟线程无法被调度。
所以这里产生了一个死锁。普通线程想要让渡锁，但是被唤醒的线程却无法获取锁，因为该线程无法被执行。

结论⌗

这个问题对想要使用虚拟线程特性的项目来说，应该是很普遍的。也许这个新特性很好，但是坑也可能不少。不用急着线上直接使用，特别是重要项目。

正如elasticsearch的这个issue中说的，该问题可能在java 23才会被解决。