JEP 444（Virtual Threads）のpinning（ピン留め）をシステムプロパティjdk.tracePinnedThreadsによるスタックトレースの出力で確認する

これは、なにをしたくて書いたもの？

前に、Virtual Threadsに関するエントリーを書きました。

Java 21で正式版になったJEP 444（Virtual Threads）に関するAPIを試す - CLOVER🍀

Virtual Threadsを使ってHTTPサーバー／クライアントを書いて、スレッドまわりの動きを確認してみる（スレッドダンプの取得付き） - CLOVER🍀

この中で、pinning（ピン留め）についての確認を少し忘れていたので続きをやろうと思います。

Virtual Threadsのpinning（ピン留め）

JEP 444（Virtual Threads）についてはこちら。

JEP 444: Virtual Threads

Virtual Threadsについては、あらためては説明しません。

こちらのエントリーを参照、ということで。

Java 21で正式版になったJEP 444（Virtual Threads）に関するAPIを試す - CLOVER🍀

pinning（ピン留め）は、プラットフォームスレッドから仮想スレッドをアンマウントできない状態のことを言います。
以下のケースがあるようです。

• When it executes code inside a synchronized block or method（synchronizedブロックやsynchronizedメソッド内のコードを実行している時）
• When it executes a native method or a foreign function（ネイティブメソッドやJEP 424のForeign Functionを実行している時）

pinning（ピン留め）が発生してもアプリケーションがおかしくなることはありませんが、スケーラビリティが代償になる可能性があります。　 数に限りのあるプラットフォームスレッドがひとつの仮想スレッドに縛られて、他の仮想スレッドを動かせず数が減ってしまうからですね。

これを回避するには、synchronizedブロックおよびsynchronizedメソッドを使わなくて済むようにすることはもちろんですが、
ロックが必要な場合はReentrantLockを使うように修正することです。

そして、synchronizedブロックでアンマウントできなくなることは以下のエントリーで確認しています。

Virtual Threadsを使ってHTTPサーバー／クライアントを書いて、スレッドまわりの動きを確認してみる（スレッドダンプの取得付き） - CLOVER🍀

ReentrantLockの利用であれば問題ないことも確認しています。

pinning（ピン留め）が発生したことは、以下の方法で記録できるようです。

• A JDK Flight Recorder (JFR) event is emitted when a thread blocks while pinned (see JDK Flight Recorder).
• The system property jdk.tracePinnedThreads triggers a stack trace when a thread blocks while pinned. Running with -Djdk.tracePinnedThreads=full prints a complete stack trace when a thread blocks while pinned, highlighting native frames and frames holding monitors. Running with -Djdk.tracePinnedThreads=short limits the output to just the problematic frames.

今回は、jdk.tracePinnedThreadsシステムプロパティを試してみたいと思います。これは、pinning（ピン留め）が発生した時に
スタックトレースを出力するものです。

指定方法には2種類あるようです。

• -Djdk.tracePinnedThreads=full … pinning（ピン留め）が発生した時に、完全なスタックトレースとネイティブフレームおよびモニターを保持しているフレームが強調表示される
• -Djdk.tracePinnedThreads=short … 問題のあるフレームのみが出力される

こちらのドキュメントにも記載があります。

コア・ライブラリ / 並行処理 / 仮想スレッド / 仮想スレッド: 採用ガイド / 長時間かつ頻繁な固定の回避

動作確認には、こちらで書いたHTTPサーバーを使うことにします。

Virtual Threadsを使ってHTTPサーバー／クライアントを書いて、スレッドまわりの動きを確認してみる（スレッドダンプの取得付き） - CLOVER🍀

では、試してみましょう。

環境

今回の環境はこちら。

$ java --version
openjdk 21.0.2 2024-01-16
OpenJDK Runtime Environment (build 21.0.2+13-Ubuntu-122.04.1)
OpenJDK 64-Bit Server VM (build 21.0.2+13-Ubuntu-122.04.1, mixed mode, sharing)


$ mvn --version
Apache Maven 3.9.6 (bc0240f3c744dd6b6ec2920b3cd08dcc295161ae)
Maven home: $HOME/.sdkman/candidates/maven/current
Java version: 21.0.2, vendor: Private Build, runtime: /usr/lib/jvm/java-21-openjdk-amd64
Default locale: ja_JP, platform encoding: UTF-8
OS name: "linux", version: "5.15.0-101-generic", arch: "amd64", family: "unix"

準備

Mavenの設定ですが、特に依存関係などは使いません。

    <properties>
        <maven.compiler.release>21</maven.compiler.release>
        <project.build.sourceEncoding>UTF-8</project.build.sourceEncoding>
        <project.reporting.outputEncoding>UTF-8</project.reporting.outputEncoding>
    </properties>

ソースコードはこちら。

src/main/java/org/littlewings/virtualthreads/SimpleHttpServer.java

package org.littlewings.virtualthreads;

import com.sun.net.httpserver.HttpHandler;
import com.sun.net.httpserver.HttpServer;

import java.io.IOException;
import java.io.OutputStream;
import java.io.UncheckedIOException;
import java.net.InetSocketAddress;
import java.net.URI;
import java.nio.charset.StandardCharsets;
import java.time.Duration;
import java.time.LocalDateTime;
import java.time.format.DateTimeFormatter;
import java.util.concurrent.Executors;
import java.util.concurrent.TimeUnit;
import java.util.concurrent.locks.ReentrantLock;
import java.util.function.Consumer;

public class SimpleHttpServer {
    private static final DateTimeFormatter FORMATTER = DateTimeFormatter.ofPattern("uuuu-MM-dd HH:mm:ss");

    private HttpServer httpServer;

    SimpleHttpServer(HttpServer httpServer) {
        this.httpServer = httpServer;
    }

    public static void main(String... args) {
        String host;
        int port;

        if (args.length > 1) {
            host = args[0];
            port = Integer.parseInt(args[1]);
        } else if (args.length > 0) {
            host = "localhost";
            port = Integer.parseInt(args[0]);
        } else {
            host = "localhost";
            port = 8080;
        }

        SimpleHttpServer simpleHttpServer = SimpleHttpServer.create(host, port);
        simpleHttpServer.start();

        Runtime.getRuntime().addShutdownHook(Thread.ofPlatform().unstarted(simpleHttpServer::stop));
    }

    private static void log(String message) {
        Thread currentThread = Thread.currentThread();
        String threadName = currentThread.getName();
        System.out.printf("[%s] - %s - %s%n", LocalDateTime.now().format(FORMATTER), threadName, message);
    }

    public static SimpleHttpServer create(String host, int port) {
        try {
            HttpServer httpServer = HttpServer.create(new InetSocketAddress(host, port), 0);

            log(String.format("jdk.virtualThreadScheduler.parallelism = %s", System.getProperty("jdk.virtualThreadScheduler.parallelism", "")));
            log(String.format("jdk.virtualThreadScheduler.maxPoolSize = %s", System.getProperty("jdk.virtualThreadScheduler.maxPoolSize", "")));
            log(String.format("jdk.tracePinnedThreads = %s", System.getProperty("jdk.tracePinnedThreads", "")));

            // httpServer.setExecutor(Executors.newVirtualThreadPerTaskExecutor());
            httpServer.setExecutor(Executors.newThreadPerTaskExecutor(Thread.ofVirtual().name("handler-", 1).factory()));
            httpServer.createContext("/", createHandler());

            return new SimpleHttpServer(httpServer);
        } catch (IOException e) {
            throw new UncheckedIOException(e);
        }
    }

    public static SimpleHttpServer create(int port) {
        return create("localhost", port);
    }

    static HttpHandler createHandler() {
        ReentrantLock lock = new ReentrantLock();
        ReentrantLock lock2 = new ReentrantLock();
        Object synchronizedLockObject = new Object();
        Object synchronizedLockObject2 = new Object();

        return httpExchange -> {
            URI requestUri = httpExchange.getRequestURI();
            String method = httpExchange.getRequestMethod();
            String requestPath = requestUri.getPath();

            log(String.format("access[%s:%s] start", method, requestPath));

            Consumer<String> writeResponse = responseString -> {
                byte[] binary = responseString.getBytes(StandardCharsets.UTF_8);

                try {
                    httpExchange.sendResponseHeaders(200, binary.length);

                    try (OutputStream os = httpExchange.getResponseBody()) {
                        os.write(binary);
                    }
                } catch (IOException e) {
                    throw new UncheckedIOException(e);
                }
            };

            Duration sleepTime = Duration.ofSeconds(3L);

            switch (requestPath) {
                case "/sleep" -> {
                    try {
                        TimeUnit.SECONDS.sleep(sleepTime.toSeconds());
                    } catch (InterruptedException e) {
                        // ignore
                    }
                    writeResponse.accept("sleep.");
                }
                case "/heavy" -> {
                    long startTime = System.currentTimeMillis();

                    while (true) {
                        for (int i = 0; i < 100000; i++) {
                            // loop
                        }

                        long elapsedTime = System.currentTimeMillis() - startTime;

                        if (elapsedTime > sleepTime.toMillis()) {
                            break;
                        }
                    }

                    writeResponse.accept("heavy.");
                }
                case "/lock" -> {
                    try {
                        lock.lock();

                        TimeUnit.SECONDS.sleep(sleepTime.toSeconds());
                    } catch (InterruptedException e) {
                        // ignore
                    } finally {
                        lock.unlock();
                    }
                    writeResponse.accept("lock.");
                }
                case "/lock2" -> {
                    try {
                        lock2.lock();

                        TimeUnit.SECONDS.sleep(sleepTime.toSeconds());
                    } catch (InterruptedException e) {
                        // ignore
                    } finally {
                        lock2.unlock();
                    }
                    writeResponse.accept("lock2.");
                }
                case "/synchronized-lock" -> {
                    synchronized (synchronizedLockObject) {
                        try {
                            TimeUnit.SECONDS.sleep(sleepTime.toSeconds());
                        } catch (InterruptedException e) {
                            // ignore
                        }
                        writeResponse.accept("synchronized lock.");
                    }
                }
                case "/synchronized-lock2" -> {
                    synchronized (synchronizedLockObject2) {
                        try {
                            TimeUnit.SECONDS.sleep(sleepTime.toSeconds());
                        } catch (InterruptedException e) {
                            // ignore
                        }
                        writeResponse.accept("synchronized lock2.");
                    }
                }
                default -> writeResponse.accept("Hello World.");
            }

            log(String.format("access[%s:%s] end", method, requestPath));
        };
    }

    public void start() {
        httpServer.start();
        log(String.format("simple http server[%s:%d], started.", httpServer.getAddress().getHostString(), httpServer.getAddress().getPort()));
    }

    public void stop() {
        httpServer.stop(1);
        log(String.format("simple http server[%s:%d], shutdown.", httpServer.getAddress().getHostString(), httpServer.getAddress().getPort()));
    }
}

基本的に、もとのエントリーと内容はほぼ変えていません。JDKのHttpServerを使って、Virtual Threadsを使った簡単なHTTPサーバーを
書いています。

    public static SimpleHttpServer create(String host, int port) {
        try {
            HttpServer httpServer = HttpServer.create(new InetSocketAddress(host, port), 0);

            log(String.format("jdk.virtualThreadScheduler.parallelism = %s", System.getProperty("jdk.virtualThreadScheduler.parallelism", "")));
            log(String.format("jdk.virtualThreadScheduler.maxPoolSize = %s", System.getProperty("jdk.virtualThreadScheduler.maxPoolSize", "")));
            log(String.format("jdk.tracePinnedThreads = %s", System.getProperty("jdk.tracePinnedThreads", "")));

            // httpServer.setExecutor(Executors.newVirtualThreadPerTaskExecutor());
            httpServer.setExecutor(Executors.newThreadPerTaskExecutor(Thread.ofVirtual().name("handler-", 1).factory()));
            httpServer.createContext("/", createHandler());

            return new SimpleHttpServer(httpServer);
        } catch (IOException e) {
            throw new UncheckedIOException(e);
        }
    }

アクセスパスに応じて、以下の5種類の処理を行います。

• /sleep … 指定した秒数だけTimeUnit#sleepでスリープ（ブロック操作の代わり）
• /heavy … 指定した秒数だけループ（CPUを消費する処理）
• /lock、/lock2 … それぞれ異なるReentrantLockのインスタンスを使ってロックを取得し、指定した秒数だけTimeUnit#sleepでスリープ
• /synchronized-lock、/synchronized-lock2 … それぞれ異なるインスタンスに対してsynchronizedでロックを取得し、指定した秒数だけTimeUnit#sleepでスリープ
• それ以外のパス … 即座にHello World.を返す

アクセスパスごとの処理は、caseになっています。

この中でpinning（ピン留め）が発生しそうなのは、/synchronized-lock、/synchronized-lock2かなと思います。/heavyも仮想スレッドが
束縛され続けますが、どうなるんでしょうね？

では、動かしてみましょう。

確認してみる

まずはコンパイル。

$ mvn compile

起動は、以下のコマンドで行います。

$ java \
    -Djdk.virtualThreadScheduler.parallelism=1 \
    -Djdk.virtualThreadScheduler.maxPoolSize=1 \
    -Djdk.tracePinnedThreads=[full or short] \
    -cp target/classes \
    org.littlewings.virtualthreads.SimpleHttpServer

システムプロパティjdk.virtualThreadScheduler.parallelismとjdk.virtualThreadScheduler.maxPoolSizeを
1にして並列度および利用可能なプラットフォームスレッドの数を1にしています。

-Djdk.tracePinnedThreads=fullと-Djdk.tracePinnedThreads=shortでそれぞれ確認してみましょう。

-Djdk.tracePinnedThreads=full

最初は、-Djdk.tracePinnedThreads=fullで確認してみましょう。

$ java \
    -Djdk.virtualThreadScheduler.parallelism=1 \
    -Djdk.virtualThreadScheduler.maxPoolSize=1 \
    -Djdk.tracePinnedThreads=full \
    -cp target/classes \
    org.littlewings.virtualthreads.SimpleHttpServer

各アクセスパスごとに確認してみます。

/sleep

TimeUnit#sleepでスリープする、/sleepにアクセス。2つのリクエストは、別々のターミナルで連続で実行しています。

## ひとつ目
$ time curl localhost:8080/sleep
sleep.
real    0m3.277s
user    0m0.014s
sys     0m0.000s


## 2つ目
$ time curl localhost:8080/sleep
sleep.
real    0m3.013s
user    0m0.008s
sys     0m0.004s

HTTPサーバー側のログ上は、変わったところはありません。

[2024-04-03 23:09:24] - handler-1 - access[GET:/sleep] start
[2024-04-03 23:09:24] - handler-2 - access[GET:/sleep] start
[2024-04-03 23:09:27] - handler-1 - access[GET:/sleep] end
[2024-04-03 23:09:27] - handler-2 - access[GET:/sleep] end

/heavy

空ループを回してCPUを消費する/heavy。

## ひとつ目
$ time curl localhost:8080/heavy
heavy.
real    0m3.014s
user    0m0.006s
sys     0m0.005s


## 2つ目
$ time curl localhost:8080/heavy
heavy.
real    0m5.642s
user    0m0.004s
sys     0m0.003s

こちらのログも、変わったところはありませんでした。

[2024-04-03 23:13:26] - handler-5 - access[GET:/heavy] start
[2024-04-03 23:13:29] - handler-5 - access[GET:/heavy] end
[2024-04-03 23:13:29] - handler-6 - access[GET:/heavy] start
[2024-04-03 23:13:32] - handler-6 - access[GET:/heavy] end

/lock

ReentrantLockを使う/lock。

## ひとつ目
$ time curl localhost:8080/lock
lock.
real    0m3.012s
user    0m0.001s
sys     0m0.009s


## 2つ目
$ time curl localhost:8080/lock
lock.
real    0m5.662s
user    0m0.006s
sys     0m0.005s

ログ。

[2024-04-03 23:26:15] - handler-9 - access[GET:/lock] start
[2024-04-03 23:26:16] - handler-10 - access[GET:/lock] start
[2024-04-03 23:26:18] - handler-9 - access[GET:/lock] end
[2024-04-03 23:26:21] - handler-10 - access[GET:/lock] end

ReentrantLockを使っているので問題ないですね。/lock2はもう飛ばすことにします。

/synchronized-lock

synchronizedでロックを取る、/synchronized-lockを試してみます。

## ひとつ目
$ time curl localhost:8080/synchronized-lock
synchronized lock.
real    0m3.013s
user    0m0.008s
sys     0m0.003s


## 2つ目
$ time curl localhost:8080/synchronized-lock
synchronized lock.
real    0m5.543s
user    0m0.001s
sys     0m0.009s

ログはこうなりました。

[2024-04-03 23:27:36] - handler-13 - access[GET:/synchronized-lock] start
Thread[#39,ForkJoinPool-1-worker-2,5,CarrierThreads]
    java.base/java.lang.VirtualThread$VThreadContinuation.onPinned(VirtualThread.java:183)
    java.base/jdk.internal.vm.Continuation.onPinned0(Continuation.java:393)
    java.base/java.lang.VirtualThread.parkNanos(VirtualThread.java:621)
    java.base/java.lang.VirtualThread.sleepNanos(VirtualThread.java:791)
    java.base/java.lang.Thread.sleep(Thread.java:556)
    java.base/java.util.concurrent.TimeUnit.sleep(TimeUnit.java:446)
    org.littlewings.virtualthreads.SimpleHttpServer.lambda$createHandler$1(SimpleHttpServer.java:160) <== monitors:1
    jdk.httpserver/com.sun.net.httpserver.Filter$Chain.doFilter(Filter.java:98)
    jdk.httpserver/sun.net.httpserver.AuthFilter.doFilter(AuthFilter.java:82)
    jdk.httpserver/com.sun.net.httpserver.Filter$Chain.doFilter(Filter.java:101)
    jdk.httpserver/sun.net.httpserver.ServerImpl$Exchange$LinkHandler.handle(ServerImpl.java:871)
    jdk.httpserver/com.sun.net.httpserver.Filter$Chain.doFilter(Filter.java:98)
    jdk.httpserver/sun.net.httpserver.ServerImpl$Exchange.run(ServerImpl.java:847)
    java.base/java.util.concurrent.ThreadPerTaskExecutor$TaskRunner.run(ThreadPerTaskExecutor.java:314)
    java.base/java.lang.VirtualThread.run(VirtualThread.java:309)
[2024-04-03 23:27:39] - handler-13 - access[GET:/synchronized-lock] end
[2024-04-03 23:27:39] - handler-14 - access[GET:/synchronized-lock] start
[2024-04-03 23:27:42] - handler-14 - access[GET:/synchronized-lock] end

なるほど、確かにスタックトレースが出力されています。しかも、どこでsynchronizedに入っているかがわかるんですね（monitors）。

一定時間が経過してから出力される、というより即出力されるようですが、連続で実行した時の2回目の方はスタックトレースが出力されて
いないんですよね。さらに追加で実行しても出力されませんでした。これはどうしてなのでしょう？

この理由は、あとで調べてみました。

/synchronized-lock2も飛ばすことにします。

-Djdk.tracePinnedThreads=short

次はHTTPサーバーを再起動して、-Djdk.tracePinnedThreads=shortで確認してみましょう。

$ java \
    -Djdk.virtualThreadScheduler.parallelism=1 \
    -Djdk.virtualThreadScheduler.maxPoolSize=1 \
    -Djdk.tracePinnedThreads=short \
    -cp target/classes \
    org.littlewings.virtualthreads.SimpleHttpServer

/synchronized-lock

もう結果がわかっているので、synchronizedでロックを取る/synchronized-lockのみで試します。

## ひとつ目
$ time curl localhost:8080/synchronized-lock
synchronized lock.
real    0m3.090s
user    0m0.005s
sys     0m0.004s


## 2つ目
$ time curl localhost:8080/synchronized-lock
synchronized lock.
real    0m5.700s
user    0m0.008s
sys     0m0.003s

ログはこのようになりました。スタックトレースが非常にシンプルというか、問題になった箇所のみが出力されています。

[2024-04-03 23:31:08] - handler-1 - access[GET:/synchronized-lock] start
Thread[#25,ForkJoinPool-1-worker-1,5,CarrierThreads]
    org.littlewings.virtualthreads.SimpleHttpServer.lambda$createHandler$1(SimpleHttpServer.java:160) <== monitors:1
[2024-04-03 23:31:11] - handler-1 - access[GET:/synchronized-lock] end
[2024-04-03 23:31:11] - handler-2 - access[GET:/synchronized-lock] start
[2024-04-03 23:31:14] - handler-2 - access[GET:/synchronized-lock] end

確かにshortです。

これで、システムプロパティjdk.tracePinnedThreadsの効果がわかりましたね。

もう少し

ここからは、少し実装を見てみましょう。

システムプロパティjdk.tracePinnedThreadsの参照箇所

こちらで見ているようです。

    private static int tracePinningMode() {
        String propValue = GetPropertyAction.privilegedGetProperty("jdk.tracePinnedThreads");
        if (propValue != null) {
            if (propValue.length() == 0 || "full".equalsIgnoreCase(propValue))
                return 1;
            if ("short".equalsIgnoreCase(propValue))
                return 2;
        }
        return 0;
    }

https://github.com/openjdk/jdk21u/blob/jdk-21.0.2%2B13/src/java.base/share/classes/java/lang/VirtualThread.java#L1160-L1169

これを見ると、システムプロパティjdk.tracePinnedThreadsのみを指定した場合はfullを指定した場合と同義になるようですね。

この結果は定数として保持され

    private static final int TRACE_PINNING_MODE = tracePinningMode();

https://github.com/openjdk/jdk21u/blob/jdk-21.0.2%2B13/src/java.base/share/classes/java/lang/VirtualThread.java#L73

VThreadContinuation#onPinnedでpinning（ピン留め）を検出した時に、システムプロパティjdk.tracePinnedThreadsが指定されていれば
即座に出力されます。

        @Override
        protected void onPinned(Continuation.Pinned reason) {
            if (TRACE_PINNING_MODE > 0) {
                boolean printAll = (TRACE_PINNING_MODE == 1);
                PinnedThreadPrinter.printStackTrace(System.out, printAll);
            }
        }

https://github.com/openjdk/jdk21u/blob/jdk-21.0.2%2B13/src/java.base/share/classes/java/lang/VirtualThread.java#L179-L185

TRACE_PINNING_MODEが1の場合はfullですね。

pinning（ピン留め）の状態かどうかは、こちらで検出します。

    @Hidden
    private boolean yield0(ContinuationScope scope, Continuation child) {
        preempted = false;

        if (scope != this.scope)
            this.yieldInfo = scope;
        int res = doYield();
        U.storeFence(); // needed to prevent certain transformations by the compiler

        assert scope != this.scope || yieldInfo == null : "scope: " + scope + " this.scope: " + this.scope + " yieldInfo: " + yieldInfo + " res: " + res;
        assert yieldInfo == null || scope == this.scope || yieldInfo instanceof Integer : "scope: " + scope + " this.scope: " + this.scope + " yieldInfo: " + yieldInfo + " res: " + res;

        if (child != null) { // TODO: ugly
            if (res != 0) {
                child.yieldInfo = res;
            } else if (yieldInfo != null) {
                assert yieldInfo instanceof Integer;
                child.yieldInfo = yieldInfo;
            } else {
                child.yieldInfo = res;
            }
            this.yieldInfo = null;
        } else {
            if (res == 0 && yieldInfo != null) {
                res = (Integer)yieldInfo;
            }
            this.yieldInfo = null;

            if (res == 0)
                onContinue();
            else
                onPinned0(res);
        }
        assert yieldInfo == null;

        return res == 0;
    }

https://github.com/openjdk/jdk21u/blob/jdk-21.0.2%2B13/src/java.base/share/classes/jdk/internal/vm/Continuation.java#L354-L390

Continuation#doYieldメソッドはnativeメソッドなので詳細は見ていません。

        int res = doYield();

そして、この結果が0でない場合はpinning（ピン留め）と判定します。

            if (res == 0)
                onContinue();
            else
                onPinned0(res);

ここからVThreadContinuation#onPinnedを呼び出すわけですね。

    private void onPinned0(int reason) {
        onPinned(pinnedReason(reason));
    }

https://github.com/openjdk/jdk21u/blob/jdk-21.0.2%2B13/src/java.base/share/classes/jdk/internal/vm/Continuation.java#L392-L394

Coninuation#pinnedReasonの内容はこちら。

    private static Pinned pinnedReason(int reason) {
        return switch (reason) {
            case 2 -> Pinned.CRITICAL_SECTION;
            case 3 -> Pinned.NATIVE;
            case 4 -> Pinned.MONITOR;
            default -> throw new AssertionError("Unknown pinned reason: " + reason);
        };
    }

https://github.com/openjdk/jdk21u/blob/jdk-21.0.2%2B13/src/java.base/share/classes/jdk/internal/vm/Continuation.java#L82-L89

Pinnedというのは列挙型で、pinning（ピン留め）の理由を表します。

    /** Reason for pinning */
    public enum Pinned {
        /** Native frame on stack */ NATIVE,
        /** Monitor held */          MONITOR,
        /** In critical section */   CRITICAL_SECTION }

https://github.com/openjdk/jdk21u/blob/jdk-21.0.2%2B13/src/java.base/share/classes/jdk/internal/vm/Continuation.java#L57-L61

あとは先ほどのシステムプロパティjdk.tracePinnedThreadsが指定されている時に、VThreadContinuation#onPinnedが呼び出している
PinnedThreadPrinter#printStackTraceで、スタックトレースを出力するということになります。

    /**
     * Prints the continuation stack trace.
     *
     * @param printAll true to print all stack frames, false to only print the
     *        frames that are native or holding a monitor
     */
    static void printStackTrace(PrintStream out, boolean printAll) {
        List<LiveStackFrame> stack = STACK_WALKER.walk(s ->
            s.map(f -> (LiveStackFrame) f)
                    .filter(f -> f.getDeclaringClass() != PinnedThreadPrinter.class)
                    .collect(Collectors.toList())
        );

        // find the closest frame that is causing the thread to be pinned
        stack.stream()
            .filter(f -> (f.isNativeMethod() || f.getMonitors().length > 0))
            .map(LiveStackFrame::getDeclaringClass)
            .findFirst()
            .ifPresentOrElse(klass -> {
                int hash = hash(stack);
                Hashes hashes = HASHES.get(klass);
                synchronized (hashes) {
                    // print the stack trace if not already seen
                    if (hashes.add(hash)) {
                        printStackTrace(stack, out, printAll);
                    }
                }
            }, () -> printStackTrace(stack, out, true));  // not found
    }

スタックトレースが1度しか出力されなかったのは？

先ほど記載した箇所に答えが載っているのですが、ここですね。

                int hash = hash(stack);
                Hashes hashes = HASHES.get(klass);
                synchronized (hashes) {
                    // print the stack trace if not already seen
                    if (hashes.add(hash)) {
                        printStackTrace(stack, out, printAll);
                    }
                }

https://github.com/openjdk/jdk21u/blob/jdk-21.0.2%2B13/src/java.base/share/classes/java/lang/PinnedThreadPrinter.java#L107-L114

スタックフレームのハッシュ値を取り、同じスタックフレームからは2度出力しないようになっています。

    /**
     * Returns a hash of the given stack trace. The hash is based on the class,
     * method and bytecode index.
     */
    private static int hash(List<LiveStackFrame> stack) {
        int hash = 0;
        for (LiveStackFrame frame : stack) {
            hash = (31 * hash) + Objects.hash(frame.getDeclaringClass(),
                    frame.getMethodName(),
                    frame.getByteCodeIndex());
        }
        return hash;
    }

https://github.com/openjdk/jdk21u/blob/jdk-21.0.2%2B13/src/java.base/share/classes/java/lang/PinnedThreadPrinter.java#L74-L86

synchronizedブロックを実行するパスに2回アクセスしたのに、1度しか出力されなかったのはこれが理由ですね。

おわりに

JEP 444（Virtual Threads）のpinning（ピン留め）が起こった際に、システムプロパティjdk.tracePinnedThreadsによる
スタックトレースが出力されることを確認してみました。

pinning（ピン留め）自体については前回も確認していましたが、この機能のことを忘れていたので今回確認しておいてよかったです。
pinning（ピン留め）というものがどういうものか、どういう条件でスタックトレースを出力させることができるかも確認できましたしね。