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

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

前回のエントリーで、JEP 444（Virtual Threads）について書きました。

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

この時には踏み込まなかった、スレッドまわりの挙動やスレッドダンプなどを確認してみたいと思います。

JEP 444（Virtual Threads）について

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

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

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

今回は、Virtual Threadsの中でも以下の点に着目して見ていこうと思います。

• 仮想スレッドはプラットフォームスレッドがマウントして駆動し、状況によってアンマウントされる
• マウント／アンマウント
  • IOなどのブロック操作でアンマウントされる
  • ReentrantLockでアンマウントされる
  • synchronizedブロック（メソッド）ではアンマウントできない
  • CPUバウンドな処理とは相性が悪い
• 新しい形式のスレッドダンプ

なお、仮想スレッドをアンマウントできない状態のことをpinning（ピン留め）といいます。pinning（ピン留め）が発生した時に
スタックトレースを出力する方法もあるのですが、それはこちらに書きました。

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

お題

JDKのHttpServerを使って、Virtual Threadsを使った簡単なHTTPサーバーを書いてみます。

HttpServer (Java SE 21 & JDK 21)

作成したHTTPサーバーに対して、いろいろ確認していってみようと思います。また、最後にHTTPクライアントを使ってテストも
してみます。

環境

今回の環境は、こちら。

$ java --version
openjdk 21.0.1 2023-10-17
OpenJDK Runtime Environment (build 21.0.1+12-Ubuntu-222.04)
OpenJDK 64-Bit Server VM (build 21.0.1+12-Ubuntu-222.04, mixed mode, sharing)


$ mvn --version
Apache Maven 3.9.6 (bc0240f3c744dd6b6ec2920b3cd08dcc295161ae)
Maven home: $HOME/.sdkman/candidates/maven/current
Java version: 21.0.1, 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-91-generic", arch: "amd64", family: "unix"

CPUは8つあります。

$ cat /proc/cpuinfo | grep processor | wc -l
8

準備

Maven依存関係などはこちら。

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

    <dependencies>
        <dependency>
            <groupId>org.junit.jupiter</groupId>
            <artifactId>junit-jupiter</artifactId>
            <version>5.10.1</version>
            <scope>test</scope>
        </dependency>
        <dependency>
            <groupId>org.assertj</groupId>
            <artifactId>assertj-core</artifactId>
            <version>3.24.2</version>
            <scope>test</scope>
        </dependency>
    </dependencies>

    <build>
        <plugins>
            <plugin>
                <artifactId>maven-surefire-plugin</artifactId>
                <version>3.1.2</version>
                <configuration>
                    <forkCount>2</forkCount>
                </configuration>
            </plugin>
        </plugins>
    </build>

JDKのHttpServerを使うだけなら特に依存関係は要らないのですが、テスト用にJUnitとAssertJを入れています。

Maven Surefire PluginにforkCountを設定しているのは、テストクラスごとにシステムプロパティをリセットしたいからです。
※テスト内で使用していますが、それは後述

HTTPサーバーを書く

それでは、お題となるHTTPサーバーを書いてみます。

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", "")));

            // 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()));
    }
}

なんかまあまあのボリュームになりました…。

HttpServerのインスタンスを構築している部分。

    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", "")));

            // 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);
        }
    }

システムプロパティjdk.virtualThreadScheduler.parallelismとjdk.virtualThreadScheduler.maxPoolSizeは今回ちょっとポイントに
なるので、ログ出力するようにしています。

HTTPサーバーはVirtual Threadsで動かすようにしています。

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

単純にExecutors#newVirtualThreadPerTaskExecutorでもよかったのですが、こちらで作成するとスレッド名が空になるようなので
ThreadFactoryを作る前にnameを指定するようにしています。こうすると、第2引数で与えた値がインクリメントされていきます。

ログ出力用のメソッドはこちらで、アクセス時にスレッド名がわかるようにしています。

    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);
    }

リクエストを受け付けた後の処理を行うメソッドはこちら。

    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));

            〜省略〜

            Duration sleepTime = Duration.ofSeconds(3L);

            switch (requestPath) {
                // アクセスパスごとの処理
            }

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

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

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

アクセスパスごとの処理は、caseになっているのでそれぞれ書いていきます。

/sleep。

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

/heavy。

                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.");
                }

/lock、/lock2。

                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.");
                }

/synchronized-lock、/synchronized-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.");
                    }
                }

いずれも待つ時間は3秒にしてあります。

            Duration sleepTime = Duration.ofSeconds(3L);

それ以外。

                default -> writeResponse.accept("Hello World.");

また、バインドするアドレスやポートはコマンドライン引数やインスタンス作成時に指定できるようにしています。

    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));
    }

〜省略〜

    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", "")));

            // 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);
    }

主題はこのあたりなので、他の部分の説明は端折ります。

動かして挙動を見てみる

ビルドして動かしてみます。

ビルド。

$ mvn compile

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

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

仮想スレッドがアンマウントできない処理に入った時に、他のプラットフォームスレッドを使って動作できないようにすることがこの設定の
意図です。

起動時のログ。

[2023-12-12 00:12:22] - main - jdk.virtualThreadScheduler.parallelism = 1
[2023-12-12 00:12:22] - main - jdk.virtualThreadScheduler.maxPoolSize = 1
[2023-12-12 00:12:22] - main - simple http server[127.0.0.1:8080], started.

確認。

$ time curl localhost:8080
Hello World.
real    0m0.012s
user    0m0.006s
sys     0m0.005s

アクセスすると、こんな感じにログが出力されます。

[2023-12-12 00:14:38] - handler-1 - access[GET:/] start
[2023-12-12 00:14:38] - handler-1 - access[GET:/] end

ここからは、2つのターミナルを使ってcurlコマンドでアクセスしつつ処理時間を見ていきます。アクセスは、基本的に同時に
行っています。

TimeUnit#sleepでスリープする、/sleepにアクセス。

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


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

2つのリクエストを処理しましたが、両方ともほぼ3秒で返ってきました。

アクセスログ上も同じです。

[2023-12-12 00:17:06] - handler-5 - access[GET:/sleep] start
[2023-12-12 00:17:06] - handler-6 - access[GET:/sleep] start
[2023-12-12 00:17:09] - handler-5 - access[GET:/sleep] end
[2023-12-12 00:17:09] - handler-6 - access[GET:/sleep] end

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

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


## 2つ目
$ time curl localhost:8080/heavy
heavy.
real    0m5.672s
user    0m0.007s
sys     0m0.000s

片方が2倍近い時間になりました。2倍以上になっているのは、各ターミナルでそれぞれコマンドを起動してるので、そのラグだと
思います…。

アクセスログを見ると、片方が動いている間はもうひとつが進められなくなっているみたいですね。

[2023-12-12 00:19:21] - handler-9 - access[GET:/heavy] start
[2023-12-12 00:19:24] - handler-9 - access[GET:/heavy] end
[2023-12-12 00:19:24] - handler-10 - access[GET:/heavy] start
[2023-12-12 00:19:27] - handler-10 - access[GET:/heavy] end

ReentrantLockを使う/lock。

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


## 2つ目
$ time curl localhost:8080/lock
lock.
real    0m5.706s
user    0m0.012s
sys     0m0.001s

/heavyと同じように時間が約2倍になりましたが、これはそもそもロックを取っているのでこうなりますよね。

アクセスログ。

[2023-12-12 00:21:23] - handler-17 - access[GET:/lock] start
[2023-12-12 00:21:23] - handler-18 - access[GET:/lock] start
[2023-12-12 00:21:26] - handler-17 - access[GET:/lock] end
[2023-12-12 00:21:29] - handler-18 - access[GET:/lock] end

では、異なるReentrantLockを使う/lockと/lock2ではどうでしょう。

## lock
$ time curl localhost:8080/lock
lock.
real    0m3.012s
user    0m0.005s
sys     0m0.005s


## lock2
$ time curl localhost:8080/lock2
lock2.
real    0m3.011s
user    0m0.008s
sys     0m0.000s

ロックしている対象が異なり、かつスリープしているのはブロックするTimeUnit#sleepなので片方が2倍の処理時間になるようなことは
ありません。

アクセスログ。

[2023-12-12 00:23:26] - handler-21 - access[GET:/lock] start
[2023-12-12 00:23:27] - handler-22 - access[GET:/lock2] start
[2023-12-12 00:23:29] - handler-21 - access[GET:/lock] end
[2023-12-12 00:23:30] - handler-22 - access[GET:/lock2] end

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

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


## 2つ目
$ time curl localhost:8080/synchronized-lock
synchronized lock.
real    0m5.655s
user    0m0.010s
sys     0m0.004s

ロックを取っているので、片方は倍くらいの時間がかかりますね。

[2023-12-12 00:25:26] - handler-25 - access[GET:/synchronized-lock] start
[2023-12-12 00:25:29] - handler-25 - access[GET:/synchronized-lock] end
[2023-12-12 00:25:29] - handler-26 - access[GET:/synchronized-lock] start
[2023-12-12 00:25:32] - handler-26 - access[GET:/synchronized-lock] end

では、別々のインスタンスに対してロックを取る/synchronized-lockと/synchronized-lock2で試してみます。

## /synchronized-lock
$ time curl localhost:8080/synchronized-lock
synchronized lock.
real    0m3.014s
user    0m0.005s
sys     0m0.006s


## /synchronized-lock2
$ time curl localhost:8080/synchronized-lock2
synchronized lock2.
real    0m5.658s
user    0m0.001s
sys     0m0.010s

こちらは、異なるインスタンスに対してロックを取得しているのに片方は倍近い時間がかかりましたね。これがsynchonizedブロックを
使っているとアンマウントできないということなのかなと思います。

アクセスログ。

[2023-12-12 00:27:30] - handler-29 - access[GET:/synchronized-lock] start
[2023-12-12 00:27:33] - handler-29 - access[GET:/synchronized-lock] end
[2023-12-12 00:27:33] - handler-30 - access[GET:/synchronized-lock2] start
[2023-12-12 00:27:36] - handler-30 - access[GET:/synchronized-lock2] end

ということは、先にsychronizedブロックのようなアンマウントできないものを動かすと、アンマウント可能な処理でも待たされることに
なるはずですね。

/synchronized-lockと/sleepで試してみましょう。

## /synchronized-lock
$ time curl localhost:8080/synchronized-lock
synchronized lock.
real    0m3.011s
user    0m0.006s
sys     0m0.004s


## /sleep
$ time curl localhost:8080/sleep
sleep.
real    0m5.678s
user    0m0.005s
sys     0m0.005s

予想通りの結果になりました。

ここまでで、以下の点は確認できたのではないかなと思います。

• 仮想スレッドはプラットフォームスレッドがマウントして駆動し、状況によってアンマウントされる
• マウント／アンマウント
  • IOなどのブロック操作でアンマウントされる
  • ReentrantLockでアンマウントされる
  • synchronizedブロック（メソッド）ではアンマウントできない
  • CPUバウンドな処理とは相性が悪い

なお、仮想スレッドをアンマウントできない状態であるpinning（ピン留め）が発生した時にスタックトレースを出力する方法もあり、
それはこちらに書いています。

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

では、並列度とプラットフォームスレッドの数を増やすとどうなるでしょうか。アンマウントできなくなっても、増やした分くらいは
動いてくれそうな気がしますね。

2にして試してみましょう。

$ java \
    -Djdk.virtualThreadScheduler.parallelism=2 \
    -Djdk.virtualThreadScheduler.maxPoolSize=2 \
    -cp target/classes \
    org.littlewings.virtualthreads.SimpleHttpServer
[2023-12-12 01:48:01] - main - jdk.virtualThreadScheduler.parallelism = 2
[2023-12-12 01:48:01] - main - jdk.virtualThreadScheduler.maxPoolSize = 2
[2023-12-12 01:48:01] - main - simple http server[127.0.0.1:8080], started.

先ほど、アクセス時間が倍になった組み合わせを試してみます。

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

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


## 2つ目
$ time curl localhost:8080/heavy
heavy.
real    0m3.009s
user    0m0.007s
sys     0m0.000s

2つ目のリクエストがひとつ目のリクエストを待たなくなりましたね。

アクセスログ。

[2023-12-12 01:48:49] - handler-1 - access[GET:/heavy] start
[2023-12-12 01:48:49] - handler-2 - access[GET:/heavy] start
[2023-12-12 01:48:52] - handler-1 - access[GET:/heavy] end
[2023-12-12 01:48:52] - handler-2 - access[GET:/heavy] end

では、別々のインスタンスに対してロックを取る/synchronized-lockと/synchronized-lock2。

## /synchronized-lock
$ time curl localhost:8080/synchronized-lock
synchronized lock.
real    0m3.010s
user    0m0.002s
sys     0m0.005s


## /synchronized-lock2
$ time curl localhost:8080/synchronized-lock2
synchronized lock2.
real    0m3.009s
user    0m0.003s
sys     0m0.004s

こちらも同傾向になりましたね。

アクセスログ。

[2023-12-12 01:50:55] - handler-5 - access[GET:/synchronized-lock] start
[2023-12-12 01:50:56] - handler-6 - access[GET:/synchronized-lock2] start
[2023-12-12 01:50:58] - handler-5 - access[GET:/synchronized-lock] end
[2023-12-12 01:50:59] - handler-6 - access[GET:/synchronized-lock2] end

というわけで、割り当てられるプラットフォームスレッドがあればそちらを使ってくれることは確認できました。

もっとも、こういう事態そのものを避けるべきなのでしょうけどね。

新しい形式のスレッドダンプを見る

次はスレッドダンプを見てみましょう。

並列度およびプラットフォームスレッド数を1にして、HTTPサーバーを起動し直します。

$ java \
    -Djdk.virtualThreadScheduler.parallelism=1 \
    -Djdk.virtualThreadScheduler.maxPoolSize=1 \
    -cp target/classes \
    org.littlewings.virtualthreads.SimpleHttpServer
[2023-12-12 22:58:34] - main - jdk.virtualThreadScheduler.parallelism = 1
[2023-12-12 22:58:34] - main - jdk.virtualThreadScheduler.maxPoolSize = 1
[2023-12-12 22:58:34] - main - simple http server[127.0.0.1:8080], started.

まずはスリープさせている時に

$ curl localhost:8080/sleep

スレッドダンプを取ってみます。

$ jcmd $(jcmd -l | grep SimpleHttpServer | cut -d' ' -f1) Thread.print

通常、jcmd [PID] [command]という指定ですが、PIDの取得はサブシェルに任せています…。
以降は$(jcmd -l | grep SimpleHttpServer | cut -d' ' -f1)という指定は「JavaアプリケーションのPIDを取得しているんだ」と思って
見てください。

結果。

13711:
2023-12-12 22:59:51
Full thread dump OpenJDK 64-Bit Server VM (21.0.1+12-Ubuntu-222.04 mixed mode, sharing):

Threads class SMR info:
_java_thread_list=0x00007fd224002120, length=15, elements={
0x00007fd2b0164be0, 0x00007fd2b0166280, 0x00007fd2b0167d30, 0x00007fd2b0169390,
0x00007fd2b016a950, 0x00007fd2b016c4b0, 0x00007fd2b016db90, 0x00007fd2b0183db0,
0x00007fd2b0187880, 0x00007fd2b01cc400, 0x00007fd2b01e41a0, 0x00007fd2b001ce80,
0x00007fd1f8043850, 0x00007fd204012740, 0x00007fd224000fe0
}

"Reference Handler" #9 [13873] daemon prio=10 os_prio=0 cpu=0.40ms elapsed=78.23s tid=0x00007fd2b0164be0 nid=13873 waiting on condition  [0x00007fd290405000]
   java.lang.Thread.State: RUNNABLE
        at java.lang.ref.Reference.waitForReferencePendingList(java.base@21.0.1/Native Method)
        at java.lang.ref.Reference.processPendingReferences(java.base@21.0.1/Reference.java:246)
        at java.lang.ref.Reference$ReferenceHandler.run(java.base@21.0.1/Reference.java:208)

"Finalizer" #10 [13874] daemon prio=8 os_prio=0 cpu=0.20ms elapsed=78.23s tid=0x00007fd2b0166280 nid=13874 in Object.wait()  [0x00007fd290305000]
   java.lang.Thread.State: WAITING (on object monitor)
        at java.lang.Object.wait0(java.base@21.0.1/Native Method)
        - waiting on <0x0000000717001670> (a java.lang.ref.NativeReferenceQueue$Lock)
        at java.lang.Object.wait(java.base@21.0.1/Object.java:366)
        at java.lang.Object.wait(java.base@21.0.1/Object.java:339)
        at java.lang.ref.NativeReferenceQueue.await(java.base@21.0.1/NativeReferenceQueue.java:48)
        at java.lang.ref.ReferenceQueue.remove0(java.base@21.0.1/ReferenceQueue.java:158)
        at java.lang.ref.NativeReferenceQueue.remove(java.base@21.0.1/NativeReferenceQueue.java:89)
        - locked <0x0000000717001670> (a java.lang.ref.NativeReferenceQueue$Lock)
        at java.lang.ref.Finalizer$FinalizerThread.run(java.base@21.0.1/Finalizer.java:173)

"Signal Dispatcher" #11 [13875] daemon prio=9 os_prio=0 cpu=0.33ms elapsed=78.23s tid=0x00007fd2b0167d30 nid=13875 waiting on condition  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Service Thread" #12 [13876] daemon prio=9 os_prio=0 cpu=0.18ms elapsed=78.23s tid=0x00007fd2b0169390 nid=13876 runnable  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Monitor Deflation Thread" #13 [13877] daemon prio=9 os_prio=0 cpu=16.01ms elapsed=78.23s tid=0x00007fd2b016a950 nid=13877 runnable  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C2 CompilerThread0" #14 [13878] daemon prio=9 os_prio=0 cpu=79.37ms elapsed=78.23s tid=0x00007fd2b016c4b0 nid=13878 waiting on condition  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE
   No compile task

"C1 CompilerThread0" #17 [13879] daemon prio=9 os_prio=0 cpu=147.73ms elapsed=78.23s tid=0x00007fd2b016db90 nid=13879 waiting on condition  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE
   No compile task

"Notification Thread" #18 [13880] daemon prio=9 os_prio=0 cpu=0.30ms elapsed=78.06s tid=0x00007fd2b0183db0 nid=13880 runnable  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Common-Cleaner" #19 [13881] daemon prio=8 os_prio=0 cpu=0.57ms elapsed=77.93s tid=0x00007fd2b0187880 nid=13881 waiting on condition  [0x00007fd23ab2d000]
   java.lang.Thread.State: TIMED_WAITING (parking)
        at jdk.internal.misc.Unsafe.park(java.base@21.0.1/Native Method)
        - parking to wait for  <0x0000000717011010> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
        at java.util.concurrent.locks.LockSupport.parkNanos(java.base@21.0.1/LockSupport.java:269)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(java.base@21.0.1/AbstractQueuedSynchronizer.java:1847)
        at java.lang.ref.ReferenceQueue.await(java.base@21.0.1/ReferenceQueue.java:71)
        at java.lang.ref.ReferenceQueue.remove0(java.base@21.0.1/ReferenceQueue.java:143)
        at java.lang.ref.ReferenceQueue.remove(java.base@21.0.1/ReferenceQueue.java:218)
        at jdk.internal.ref.CleanerImpl.run(java.base@21.0.1/CleanerImpl.java:140)
        at java.lang.Thread.runWith(java.base@21.0.1/Thread.java:1596)
        at java.lang.Thread.run(java.base@21.0.1/Thread.java:1583)
        at jdk.internal.misc.InnocuousThread.run(java.base@21.0.1/InnocuousThread.java:186)

"idle-timeout-task" #20 [13882] daemon prio=5 os_prio=0 cpu=1.03ms elapsed=77.68s tid=0x00007fd2b01cc400 nid=13882 in Object.wait()  [0x00007fd23aa16000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
        at java.lang.Object.wait0(java.base@21.0.1/Native Method)
        - waiting on <0x000000071706e308> (a java.util.TaskQueue)
        at java.lang.Object.wait(java.base@21.0.1/Object.java:366)
        at java.util.TimerThread.mainLoop(java.base@21.0.1/Timer.java:563)
        - locked <0x000000071706e308> (a java.util.TaskQueue)
        at java.util.TimerThread.run(java.base@21.0.1/Timer.java:516)

"HTTP-Dispatcher" #21 [13884] prio=5 os_prio=0 cpu=50.94ms elapsed=77.59s tid=0x00007fd2b01e41a0 nid=13884 runnable  [0x00007fd23a80b000]
   java.lang.Thread.State: RUNNABLE
        at sun.nio.ch.EPoll.wait(java.base@21.0.1/Native Method)
        at sun.nio.ch.EPollSelectorImpl.doSelect(java.base@21.0.1/EPollSelectorImpl.java:121)
        at sun.nio.ch.SelectorImpl.lockAndDoSelect(java.base@21.0.1/SelectorImpl.java:130)
        - locked <0x000000071706bc48> (a sun.nio.ch.Util$2)
        - locked <0x000000071706b8c0> (a sun.nio.ch.EPollSelectorImpl)
        at sun.nio.ch.SelectorImpl.select(java.base@21.0.1/SelectorImpl.java:142)
        at sun.net.httpserver.ServerImpl$Dispatcher.run(jdk.httpserver@21.0.1/ServerImpl.java:474)
        at java.lang.Thread.runWith(java.base@21.0.1/Thread.java:1596)
        at java.lang.Thread.run(java.base@21.0.1/Thread.java:1583)

"DestroyJavaVM" #23 [13712] prio=5 os_prio=0 cpu=276.12ms elapsed=77.56s tid=0x00007fd2b001ce80 nid=13712 waiting on condition  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"ForkJoinPool-1-worker-1" #25 [14092] daemon prio=5 os_prio=0 cpu=25.68ms elapsed=2.32s tid=0x00007fd1f8043850 nid=14092 waiting on condition  [0x00007fd23a90b000]
   java.lang.Thread.State: TIMED_WAITING (parking)
        at jdk.internal.misc.Unsafe.park(java.base@21.0.1/Native Method)
        - parking to wait for  <0x0000000716f0c408> (a java.util.concurrent.ForkJoinPool)
        at java.util.concurrent.locks.LockSupport.parkUntil(java.base@21.0.1/LockSupport.java:449)
        at java.util.concurrent.ForkJoinPool.awaitWork(java.base@21.0.1/ForkJoinPool.java:1891)
        at java.util.concurrent.ForkJoinPool.runWorker(java.base@21.0.1/ForkJoinPool.java:1809)
        at java.util.concurrent.ForkJoinWorkerThread.run(java.base@21.0.1/ForkJoinWorkerThread.java:188)

"VirtualThread-unparker" #26 [14093] daemon prio=5 os_prio=0 cpu=0.38ms elapsed=2.25s tid=0x00007fd204012740 nid=14093 waiting on condition  [0x00007fd23a70b000]
   java.lang.Thread.State: TIMED_WAITING (parking)
        at jdk.internal.misc.Unsafe.park(java.base@21.0.1/Native Method)
        - parking to wait for  <0x0000000716f14a70> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
        at java.util.concurrent.locks.LockSupport.parkNanos(java.base@21.0.1/LockSupport.java:269)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(java.base@21.0.1/AbstractQueuedSynchronizer.java:1758)
        at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(java.base@21.0.1/ScheduledThreadPoolExecutor.java:1182)
        at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(java.base@21.0.1/ScheduledThreadPoolExecutor.java:899)
        at java.util.concurrent.ThreadPoolExecutor.getTask(java.base@21.0.1/ThreadPoolExecutor.java:1070)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@21.0.1/ThreadPoolExecutor.java:1130)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@21.0.1/ThreadPoolExecutor.java:642)
        at java.lang.Thread.runWith(java.base@21.0.1/Thread.java:1596)
        at java.lang.Thread.run(java.base@21.0.1/Thread.java:1583)
        at jdk.internal.misc.InnocuousThread.run(java.base@21.0.1/InnocuousThread.java:186)

"Attach Listener" #27 [14136] daemon prio=9 os_prio=0 cpu=0.30ms elapsed=0.10s tid=0x00007fd224000fe0 nid=14136 waiting on condition  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"VM Thread" os_prio=0 cpu=4.86ms elapsed=78.45s tid=0x00007fd2b0157850 nid=13872 runnable

"GC Thread#0" os_prio=0 cpu=0.25ms elapsed=79.36s tid=0x00007fd2b0084aa0 nid=13713 runnable

"G1 Main Marker" os_prio=0 cpu=0.25ms elapsed=79.36s tid=0x00007fd2b0095950 nid=13714 runnable

"G1 Conc#0" os_prio=0 cpu=0.20ms elapsed=79.36s tid=0x00007fd2b0096910 nid=13715 runnable

"G1 Refine#0" os_prio=0 cpu=0.12ms elapsed=79.36s tid=0x00007fd2b0122430 nid=13716 runnable

"G1 Service" os_prio=0 cpu=4.68ms elapsed=79.36s tid=0x00007fd2b0123400 nid=13717 runnable

"VM Periodic Task Thread" os_prio=0 cpu=85.24ms elapsed=78.62s tid=0x00007fd2b013d0f0 nid=13867 waiting on condition

JNI global refs: 16, weak refs: 0

TimeUnit#sleepで止まっているスレッドがいません。そもそも、handler-Nという名前のスレッドもいませんね。どうやら
Virtual Threadsは表示されないようです。

Virtual Threadsのスタックトレースを含むには、Thread.dump_to_fileを使うようです。

$ jcmd $(jcmd -l | grep SimpleHttpServer | cut -d' ' -f1) help Thread.dump_to_file
13711:
Thread.dump_to_file
Dump threads, with stack traces, to a file in plain text or JSON format.

Impact: Medium: Depends on the number of threads.

Syntax : Thread.dump_to_file [options] <filepath>

Arguments:
        filepath :  The file path to the output file (STRING, no default value)

Options: (options must be specified using the <key> or <key>=<value> syntax)
        -overwrite : [optional] May overwrite existing file (BOOLEAN, false)
        -format : [optional] Output format ("plain" or "json") (STRING, plain)

ちなみに、このコマンドはjcmdのドキュメントには載っていなさそうです…。

jcmdコマンド

もう1度スリープさせて

$ curl localhost:8080/sleep

スレッドダンプを取得。出力形式はまずはテキスト（plain）にしています。また、このコマンドは出力結果がファイルになります。

$ jcmd $(jcmd -l | grep SimpleHttpServer | cut -d' ' -f1) Thread.dump_to_file -format=plain thread_dump.txt

ファイルが作成されました。

13711:
Created /path/to/thread_dump.txt

中身を見てみます。

thread_dump.txt

13711
2023-12-12T14:07:43.882089998Z
21.0.1+12-Ubuntu-222.04

#9 "Reference Handler"
      java.base/java.lang.ref.Reference.waitForReferencePendingList(Native Method)
      java.base/java.lang.ref.Reference.processPendingReferences(Reference.java:246)
      java.base/java.lang.ref.Reference$ReferenceHandler.run(Reference.java:208)

#10 "Finalizer"
      java.base/java.lang.Object.wait0(Native Method)
      java.base/java.lang.Object.wait(Object.java:366)
      java.base/java.lang.Object.wait(Object.java:339)
      java.base/java.lang.ref.NativeReferenceQueue.await(NativeReferenceQueue.java:48)
      java.base/java.lang.ref.ReferenceQueue.remove0(ReferenceQueue.java:158)
      java.base/java.lang.ref.NativeReferenceQueue.remove(NativeReferenceQueue.java:89)
      java.base/java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:173)

#11 "Signal Dispatcher"

#18 "Notification Thread"

#19 "Common-Cleaner"
      java.base/jdk.internal.misc.Unsafe.park(Native Method)
      java.base/java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:269)
      java.base/java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:1847)
      java.base/java.lang.ref.ReferenceQueue.await(ReferenceQueue.java:71)
      java.base/java.lang.ref.ReferenceQueue.remove0(ReferenceQueue.java:143)
      java.base/java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:218)
      java.base/jdk.internal.ref.CleanerImpl.run(CleanerImpl.java:140)
      java.base/java.lang.Thread.run(Thread.java:1583)
      java.base/jdk.internal.misc.InnocuousThread.run(InnocuousThread.java:186)

#20 "idle-timeout-task"
      java.base/java.lang.Object.wait0(Native Method)
      java.base/java.lang.Object.wait(Object.java:366)
      java.base/java.util.TimerThread.mainLoop(Timer.java:563)
      java.base/java.util.TimerThread.run(Timer.java:516)

#21 "HTTP-Dispatcher"
      java.base/sun.nio.ch.EPoll.wait(Native Method)
      java.base/sun.nio.ch.EPollSelectorImpl.doSelect(EPollSelectorImpl.java:121)
      java.base/sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:130)
      java.base/sun.nio.ch.SelectorImpl.select(SelectorImpl.java:142)
      jdk.httpserver/sun.net.httpserver.ServerImpl$Dispatcher.run(ServerImpl.java:474)
      java.base/java.lang.Thread.run(Thread.java:1583)

#23 "DestroyJavaVM"

#27 "Attach Listener"
      java.base/java.lang.Thread.getStackTrace(Thread.java:2450)
      java.base/jdk.internal.vm.ThreadDumper.dumpThread(ThreadDumper.java:162)
      java.base/jdk.internal.vm.ThreadDumper.lambda$dumpThreads$0(ThreadDumper.java:155)
      java.base/java.util.stream.ReferencePipeline$2$1.accept(ReferencePipeline.java:179)
      java.base/java.util.Spliterators$ArraySpliterator.forEachRemaining(Spliterators.java:1024)
      java.base/java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:509)
      java.base/java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:499)
      java.base/java.util.stream.StreamSpliterators$WrappingSpliterator.forEachRemaining(StreamSpliterators.java:310)
      java.base/java.util.stream.Streams$ConcatSpliterator.forEachRemaining(Streams.java:734)
      java.base/java.util.stream.ReferencePipeline$Head.forEach(ReferencePipeline.java:762)
      java.base/jdk.internal.vm.ThreadDumper.dumpThreads(ThreadDumper.java:155)
      java.base/jdk.internal.vm.ThreadDumper.dumpThreads(ThreadDumper.java:151)
      java.base/jdk.internal.vm.ThreadDumper.dumpThreadsToFile(ThreadDumper.java:117)
      java.base/jdk.internal.vm.ThreadDumper.dumpThreads(ThreadDumper.java:67)

#29 "handler-3" virtual
      java.base/java.lang.VirtualThread.parkNanos(VirtualThread.java:621)
      java.base/java.lang.VirtualThread.sleepNanos(VirtualThread.java:793)
      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:109)
      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)

#30 "ForkJoinPool-1-worker-2"
      java.base/jdk.internal.misc.Unsafe.park(Native Method)
      java.base/java.util.concurrent.locks.LockSupport.parkUntil(LockSupport.java:449)
      java.base/java.util.concurrent.ForkJoinPool.awaitWork(ForkJoinPool.java:1891)
      java.base/java.util.concurrent.ForkJoinPool.runWorker(ForkJoinPool.java:1809)
      java.base/java.util.concurrent.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:188)

#26 "VirtualThread-unparker"
      java.base/jdk.internal.misc.Unsafe.park(Native Method)
      java.base/java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:269)
      java.base/java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:1758)
      java.base/java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1182)
      java.base/java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:899)
      java.base/java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1070)
      java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130)
      java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:642)
      java.base/java.lang.Thread.run(Thread.java:1583)
      java.base/jdk.internal.misc.InnocuousThread.run(InnocuousThread.java:186)

今度はVirtual Threadsが出現しました。

#29 "handler-3" virtual
      java.base/java.lang.VirtualThread.parkNanos(VirtualThread.java:621)
      java.base/java.lang.VirtualThread.sleepNanos(VirtualThread.java:793)
      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:109)
      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)

Thread.dump_to_fileはformat=jsonでJSON形式でも出力できます。

$ jcmd $(jcmd -l | grep SimpleHttpServer | cut -d' ' -f1) Thread.dump_to_file -format=json thread_dump.json

結果。

thread_dump.json

{
  "threadDump": {
    "processId": "13711",
    "time": "2023-12-12T14:11:05.724062912Z",
    "runtimeVersion": "21.0.1+12-Ubuntu-222.04",
    "threadContainers": [
      {
        "container": "<root>",
        "parent": null,
        "owner": null,
        "threads": [
         {
           "tid": "9",
           "name": "Reference Handler",
           "stack": [
              "java.base\/java.lang.ref.Reference.waitForReferencePendingList(Native Method)",
              "java.base\/java.lang.ref.Reference.processPendingReferences(Reference.java:246)",
              "java.base\/java.lang.ref.Reference$ReferenceHandler.run(Reference.java:208)"
           ]
         },
         {
           "tid": "10",
           "name": "Finalizer",
           "stack": [
              "java.base\/java.lang.Object.wait0(Native Method)",
              "java.base\/java.lang.Object.wait(Object.java:366)",
              "java.base\/java.lang.Object.wait(Object.java:339)",
              "java.base\/java.lang.ref.NativeReferenceQueue.await(NativeReferenceQueue.java:48)",
              "java.base\/java.lang.ref.ReferenceQueue.remove0(ReferenceQueue.java:158)",
              "java.base\/java.lang.ref.NativeReferenceQueue.remove(NativeReferenceQueue.java:89)",
              "java.base\/java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:173)"
           ]
         },
         {
           "tid": "11",
           "name": "Signal Dispatcher",
           "stack": [
           ]
         },
         {
           "tid": "18",
           "name": "Notification Thread",
           "stack": [
           ]
         },
         {
           "tid": "19",
           "name": "Common-Cleaner",
           "stack": [
              "java.base\/jdk.internal.misc.Unsafe.park(Native Method)",
              "java.base\/java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:269)",
              "java.base\/java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:1847)",
              "java.base\/java.lang.ref.ReferenceQueue.await(ReferenceQueue.java:71)",
              "java.base\/java.lang.ref.ReferenceQueue.remove0(ReferenceQueue.java:143)",
              "java.base\/java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:218)",
              "java.base\/jdk.internal.ref.CleanerImpl.run(CleanerImpl.java:140)",
              "java.base\/java.lang.Thread.run(Thread.java:1583)",
              "java.base\/jdk.internal.misc.InnocuousThread.run(InnocuousThread.java:186)"
           ]
         },
         {
           "tid": "20",
           "name": "idle-timeout-task",
           "stack": [
              "java.base\/java.lang.Object.wait0(Native Method)",
              "java.base\/java.lang.Object.wait(Object.java:366)",
              "java.base\/java.util.TimerThread.mainLoop(Timer.java:563)",
              "java.base\/java.util.TimerThread.run(Timer.java:516)"
           ]
         },
         {
           "tid": "21",
           "name": "HTTP-Dispatcher",
           "stack": [
              "java.base\/sun.nio.ch.EPoll.wait(Native Method)",
              "java.base\/sun.nio.ch.EPollSelectorImpl.doSelect(EPollSelectorImpl.java:121)",
              "java.base\/sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:130)",
              "java.base\/sun.nio.ch.SelectorImpl.select(SelectorImpl.java:142)",
              "jdk.httpserver\/sun.net.httpserver.ServerImpl$Dispatcher.run(ServerImpl.java:474)",
              "java.base\/java.lang.Thread.run(Thread.java:1583)"
           ]
         },
         {
           "tid": "23",
           "name": "DestroyJavaVM",
           "stack": [
           ]
         },
         {
           "tid": "27",
           "name": "Attach Listener",
           "stack": [
              "java.base\/java.lang.Thread.getStackTrace(Thread.java:2450)",
              "java.base\/jdk.internal.vm.ThreadDumper.dumpThreadToJson(ThreadDumper.java:264)",
              "java.base\/jdk.internal.vm.ThreadDumper.dumpThreadsToJson(ThreadDumper.java:237)",
              "java.base\/jdk.internal.vm.ThreadDumper.dumpThreadsToJson(ThreadDumper.java:201)",
              "java.base\/jdk.internal.vm.ThreadDumper.dumpThreadsToFile(ThreadDumper.java:115)",
              "java.base\/jdk.internal.vm.ThreadDumper.dumpThreadsToJson(ThreadDumper.java:84)"
           ]
         }
        ],
        "threadCount": "9"
      },
      {
        "container": "ForkJoinPool.commonPool\/jdk.internal.vm.SharedThreadContainer@7350b626",
        "parent": "<root>",
        "owner": null,
        "threads": [
        ],
        "threadCount": "0"
      },
      {
        "container": "java.util.concurrent.ThreadPoolExecutor@486cc147",
        "parent": "<root>",
        "owner": null,
        "threads": [
        ],
        "threadCount": "0"
      },
      {
        "container": "java.util.concurrent.ThreadPerTaskExecutor@45a37b8c",
        "parent": "<root>",
        "owner": null,
        "threads": [
         {
           "tid": "32",
           "name": "handler-5",
           "stack": [
              "java.base\/java.lang.VirtualThread.parkNanos(VirtualThread.java:621)",
              "java.base\/java.lang.VirtualThread.sleepNanos(VirtualThread.java:793)",
              "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:109)",
              "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)"
           ]
         }
        ],
        "threadCount": "1"
      },
      {
        "container": "ForkJoinPool-1\/jdk.internal.vm.SharedThreadContainer@a5da302",
        "parent": "<root>",
        "owner": null,
        "threads": [
         {
           "tid": "33",
           "name": "ForkJoinPool-1-worker-3",
           "stack": [
              "java.base\/jdk.internal.misc.Unsafe.park(Native Method)",
              "java.base\/java.util.concurrent.locks.LockSupport.parkUntil(LockSupport.java:449)",
              "java.base\/java.util.concurrent.ForkJoinPool.awaitWork(ForkJoinPool.java:1891)",
              "java.base\/java.util.concurrent.ForkJoinPool.runWorker(ForkJoinPool.java:1809)",
              "java.base\/java.util.concurrent.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:188)"
           ]
         }
        ],
        "threadCount": "1"
      },
      {
        "container": "java.util.concurrent.ScheduledThreadPoolExecutor@4d8bd5e9",
        "parent": "<root>",
        "owner": null,
        "threads": [
         {
           "tid": "26",
           "name": "VirtualThread-unparker",
           "stack": [
              "java.base\/jdk.internal.misc.Unsafe.park(Native Method)",
              "java.base\/java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:269)",
              "java.base\/java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:1758)",
              "java.base\/java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1182)",
              "java.base\/java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:899)",
              "java.base\/java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1070)",
              "java.base\/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130)",
              "java.base\/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:642)",
              "java.base\/java.lang.Thread.run(Thread.java:1583)",
              "java.base\/jdk.internal.misc.InnocuousThread.run(InnocuousThread.java:186)"
           ]
         }
        ],
        "threadCount": "1"
      }
    ]
  }
}

Virtual Threadsはこの部分ですね。

      {
        "container": "java.util.concurrent.ThreadPerTaskExecutor@45a37b8c",
        "parent": "<root>",
        "owner": null,
        "threads": [
         {
           "tid": "32",
           "name": "handler-5",
           "stack": [
              "java.base\/java.lang.VirtualThread.parkNanos(VirtualThread.java:621)",
              "java.base\/java.lang.VirtualThread.sleepNanos(VirtualThread.java:793)",
              "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:109)",
              "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)"
           ]
         }
        ],
        "threadCount": "1"
      },

JSON形式なのでちょっとビックリしますが、Virtual Threadsがどこに属しているかなどがわかって良いですね。

-formatを指定しない場合は、plainになります。

$ jcmd $(jcmd -l | grep SimpleHttpServer | cut -d' ' -f1) Thread.dump_to_file thread_dump.txt

また、デフォルトでは出力先にすでにファイルがある場合は上書きしません。

$ jcmd $(jcmd -l | grep SimpleHttpServer | cut -d' ' -f1) Thread.dump_to_file thread_dump.txt
13711:
/path/to/thread_dump.txt exists, use -overwrite to overwrite

存在するファイルを上書きする場合は、-overwriteオプションを指定します。

$ jcmd $(jcmd -l | grep SimpleHttpServer | cut -d' ' -f1) Thread.dump_to_file -overwrite thread_dump.txt
13711:
Created /path/to/thread_dump.txt

他もいくつか見てみましょう。

synchronizedを使った場合。

$ curl localhost:8080/synchronized-lock

スレッドダンプを取得して

$ jcmd $(jcmd -l | grep SimpleHttpServer | cut -d' ' -f1) Thread.dump_to_file -format=json -overwrite thread_dump.json

確認。

{
  "threadDump": {
    "processId": "13711",
    "time": "2023-12-12T14:22:17.829867481Z",
    "runtimeVersion": "21.0.1+12-Ubuntu-222.04",
    "threadContainers": [
      {
        "container": "<root>",
        "parent": null,
        "owner": null,
        "threads": [
         {
           "tid": "9",
           "name": "Reference Handler",
           "stack": [
              "java.base\/java.lang.ref.Reference.waitForReferencePendingList(Native Method)",
              "java.base\/java.lang.ref.Reference.processPendingReferences(Reference.java:246)",
              "java.base\/java.lang.ref.Reference$ReferenceHandler.run(Reference.java:208)"
           ]
         },
         {
           "tid": "10",
           "name": "Finalizer",
           "stack": [
              "java.base\/java.lang.Object.wait0(Native Method)",
              "java.base\/java.lang.Object.wait(Object.java:366)",
              "java.base\/java.lang.Object.wait(Object.java:339)",
              "java.base\/java.lang.ref.NativeReferenceQueue.await(NativeReferenceQueue.java:48)",
              "java.base\/java.lang.ref.ReferenceQueue.remove0(ReferenceQueue.java:158)",
              "java.base\/java.lang.ref.NativeReferenceQueue.remove(NativeReferenceQueue.java:89)",
              "java.base\/java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:173)"
           ]
         },
         {
           "tid": "11",
           "name": "Signal Dispatcher",
           "stack": [
           ]
         },
         {
           "tid": "18",
           "name": "Notification Thread",
           "stack": [
           ]
         },
         {
           "tid": "19",
           "name": "Common-Cleaner",
           "stack": [
              "java.base\/jdk.internal.misc.Unsafe.park(Native Method)",
              "java.base\/java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:269)",
              "java.base\/java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:1847)",
              "java.base\/java.lang.ref.ReferenceQueue.await(ReferenceQueue.java:71)",
              "java.base\/java.lang.ref.ReferenceQueue.remove0(ReferenceQueue.java:143)",
              "java.base\/java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:218)",
              "java.base\/jdk.internal.ref.CleanerImpl.run(CleanerImpl.java:140)",
              "java.base\/java.lang.Thread.run(Thread.java:1583)",
              "java.base\/jdk.internal.misc.InnocuousThread.run(InnocuousThread.java:186)"
           ]
         },
         {
           "tid": "20",
           "name": "idle-timeout-task",
           "stack": [
              "java.base\/java.lang.Object.wait0(Native Method)",
              "java.base\/java.lang.Object.wait(Object.java:366)",
              "java.base\/java.util.TimerThread.mainLoop(Timer.java:563)",
              "java.base\/java.util.TimerThread.run(Timer.java:516)"
           ]
         },
         {
           "tid": "21",
           "name": "HTTP-Dispatcher",
           "stack": [
              "java.base\/sun.nio.ch.EPoll.wait(Native Method)",
              "java.base\/sun.nio.ch.EPollSelectorImpl.doSelect(EPollSelectorImpl.java:121)",
              "java.base\/sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:130)",
              "java.base\/sun.nio.ch.SelectorImpl.select(SelectorImpl.java:142)",
              "jdk.httpserver\/sun.net.httpserver.ServerImpl$Dispatcher.run(ServerImpl.java:474)",
              "java.base\/java.lang.Thread.run(Thread.java:1583)"
           ]
         },
         {
           "tid": "23",
           "name": "DestroyJavaVM",
           "stack": [
           ]
         },
         {
           "tid": "27",
           "name": "Attach Listener",
           "stack": [
              "java.base\/java.lang.Thread.getStackTrace(Thread.java:2450)",
              "java.base\/jdk.internal.vm.ThreadDumper.dumpThreadToJson(ThreadDumper.java:264)",
              "java.base\/jdk.internal.vm.ThreadDumper.dumpThreadsToJson(ThreadDumper.java:237)",
              "java.base\/jdk.internal.vm.ThreadDumper.dumpThreadsToJson(ThreadDumper.java:201)",
              "java.base\/jdk.internal.vm.ThreadDumper.dumpThreadsToFile(ThreadDumper.java:115)",
              "java.base\/jdk.internal.vm.ThreadDumper.dumpThreadsToJson(ThreadDumper.java:84)"
           ]
         }
        ],
        "threadCount": "9"
      },
      {
        "container": "ForkJoinPool.commonPool\/jdk.internal.vm.SharedThreadContainer@7350b626",
        "parent": "<root>",
        "owner": null,
        "threads": [
        ],
        "threadCount": "0"
      },
      {
        "container": "java.util.concurrent.ThreadPoolExecutor@486cc147",
        "parent": "<root>",
        "owner": null,
        "threads": [
        ],
        "threadCount": "0"
      },
      {
        "container": "java.util.concurrent.ThreadPerTaskExecutor@45a37b8c",
        "parent": "<root>",
        "owner": null,
        "threads": [
         {
           "tid": "41",
           "name": "handler-11",
           "stack": [
              "java.base\/jdk.internal.misc.Unsafe.park(Native Method)",
              "java.base\/java.lang.VirtualThread.parkOnCarrierThread(VirtualThread.java:665)",
              "java.base\/java.lang.VirtualThread.parkNanos(VirtualThread.java:636)",
              "java.base\/java.lang.VirtualThread.sleepNanos(VirtualThread.java:793)",
              "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:159)",
              "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)"
           ]
         }
        ],
        "threadCount": "1"
      },
      {
        "container": "ForkJoinPool-1\/jdk.internal.vm.SharedThreadContainer@a5da302",
        "parent": "<root>",
        "owner": null,
        "threads": [
         {
           "tid": "42",
           "name": "ForkJoinPool-1-worker-6",
           "stack": [
              "java.base\/jdk.internal.vm.Continuation.run(Continuation.java:248)",
              "java.base\/java.lang.VirtualThread.runContinuation(VirtualThread.java:221)",
              "java.base\/java.util.concurrent.ForkJoinTask$RunnableExecuteAction.exec(ForkJoinTask.java:1423)",
              "java.base\/java.util.concurrent.ForkJoinTask.doExec(ForkJoinTask.java:387)",
              "java.base\/java.util.concurrent.ForkJoinPool$WorkQueue.topLevelExec(ForkJoinPool.java:1312)",
              "java.base\/java.util.concurrent.ForkJoinPool.scan(ForkJoinPool.java:1843)",
              "java.base\/java.util.concurrent.ForkJoinPool.runWorker(ForkJoinPool.java:1808)",
              "java.base\/java.util.concurrent.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:188)"
           ]
         }
        ],
        "threadCount": "1"
      },
      {
        "container": "java.util.concurrent.ScheduledThreadPoolExecutor@4d8bd5e9",
        "parent": "<root>",
        "owner": null,
        "threads": [
         {
           "tid": "26",
           "name": "VirtualThread-unparker",
           "stack": [
              "java.base\/jdk.internal.misc.Unsafe.park(Native Method)",
              "java.base\/java.util.concurrent.locks.LockSupport.park(LockSupport.java:371)",
              "java.base\/java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionNode.block(AbstractQueuedSynchronizer.java:519)",
              "java.base\/java.util.concurrent.ForkJoinPool.unmanagedBlock(ForkJoinPool.java:3780)",
              "java.base\/java.util.concurrent.ForkJoinPool.managedBlock(ForkJoinPool.java:3725)",
              "java.base\/java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:1707)",
              "java.base\/java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1170)",
              "java.base\/java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:899)",
              "java.base\/java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1070)",
              "java.base\/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130)",
              "java.base\/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:642)",
              "java.base\/java.lang.Thread.run(Thread.java:1583)",
              "java.base\/jdk.internal.misc.InnocuousThread.run(InnocuousThread.java:186)"
           ]
         }
        ],
        "threadCount": "1"
      }
    ]
  }
}

以降はスレッドダンプを取得する箇所は省略します。

ReentrantLock。

$ curl localhost:8080/lock

結果。

{
  "threadDump": {
    "processId": "13711",
    "time": "2023-12-12T14:23:14.386811163Z",
    "runtimeVersion": "21.0.1+12-Ubuntu-222.04",
    "threadContainers": [
      {
        "container": "<root>",
        "parent": null,
        "owner": null,
        "threads": [
         {
           "tid": "9",
           "name": "Reference Handler",
           "stack": [
              "java.base\/java.lang.ref.Reference.waitForReferencePendingList(Native Method)",
              "java.base\/java.lang.ref.Reference.processPendingReferences(Reference.java:246)",
              "java.base\/java.lang.ref.Reference$ReferenceHandler.run(Reference.java:208)"
           ]
         },
         {
           "tid": "10",
           "name": "Finalizer",
           "stack": [
              "java.base\/java.lang.Object.wait0(Native Method)",
              "java.base\/java.lang.Object.wait(Object.java:366)",
              "java.base\/java.lang.Object.wait(Object.java:339)",
              "java.base\/java.lang.ref.NativeReferenceQueue.await(NativeReferenceQueue.java:48)",
              "java.base\/java.lang.ref.ReferenceQueue.remove0(ReferenceQueue.java:158)",
              "java.base\/java.lang.ref.NativeReferenceQueue.remove(NativeReferenceQueue.java:89)",
              "java.base\/java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:173)"
           ]
         },
         {
           "tid": "11",
           "name": "Signal Dispatcher",
           "stack": [
           ]
         },
         {
           "tid": "18",
           "name": "Notification Thread",
           "stack": [
           ]
         },
         {
           "tid": "19",
           "name": "Common-Cleaner",
           "stack": [
              "java.base\/jdk.internal.misc.Unsafe.park(Native Method)",
              "java.base\/java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:269)",
              "java.base\/java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:1847)",
              "java.base\/java.lang.ref.ReferenceQueue.await(ReferenceQueue.java:71)",
              "java.base\/java.lang.ref.ReferenceQueue.remove0(ReferenceQueue.java:143)",
              "java.base\/java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:218)",
              "java.base\/jdk.internal.ref.CleanerImpl.run(CleanerImpl.java:140)",
              "java.base\/java.lang.Thread.run(Thread.java:1583)",
              "java.base\/jdk.internal.misc.InnocuousThread.run(InnocuousThread.java:186)"
           ]
         },
         {
           "tid": "20",
           "name": "idle-timeout-task",
           "stack": [
              "java.base\/java.lang.Object.wait0(Native Method)",
              "java.base\/java.lang.Object.wait(Object.java:366)",
              "java.base\/java.util.TimerThread.mainLoop(Timer.java:563)",
              "java.base\/java.util.TimerThread.run(Timer.java:516)"
           ]
         },
         {
           "tid": "21",
           "name": "HTTP-Dispatcher",
           "stack": [
              "java.base\/sun.nio.ch.EPoll.wait(Native Method)",
              "java.base\/sun.nio.ch.EPollSelectorImpl.doSelect(EPollSelectorImpl.java:121)",
              "java.base\/sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:130)",
              "java.base\/sun.nio.ch.SelectorImpl.select(SelectorImpl.java:142)",
              "jdk.httpserver\/sun.net.httpserver.ServerImpl$Dispatcher.run(ServerImpl.java:474)",
              "java.base\/java.lang.Thread.run(Thread.java:1583)"
           ]
         },
         {
           "tid": "23",
           "name": "DestroyJavaVM",
           "stack": [
           ]
         },
         {
           "tid": "27",
           "name": "Attach Listener",
           "stack": [
              "java.base\/java.lang.Thread.getStackTrace(Thread.java:2450)",
              "java.base\/jdk.internal.vm.ThreadDumper.dumpThreadToJson(ThreadDumper.java:264)",
              "java.base\/jdk.internal.vm.ThreadDumper.dumpThreadsToJson(ThreadDumper.java:237)",
              "java.base\/jdk.internal.vm.ThreadDumper.dumpThreadsToJson(ThreadDumper.java:201)",
              "java.base\/jdk.internal.vm.ThreadDumper.dumpThreadsToFile(ThreadDumper.java:115)",
              "java.base\/jdk.internal.vm.ThreadDumper.dumpThreadsToJson(ThreadDumper.java:84)"
           ]
         }
        ],
        "threadCount": "9"
      },
      {
        "container": "ForkJoinPool.commonPool\/jdk.internal.vm.SharedThreadContainer@7350b626",
        "parent": "<root>",
        "owner": null,
        "threads": [
        ],
        "threadCount": "0"
      },
      {
        "container": "java.util.concurrent.ThreadPoolExecutor@486cc147",
        "parent": "<root>",
        "owner": null,
        "threads": [
        ],
        "threadCount": "0"
      },
      {
        "container": "java.util.concurrent.ThreadPerTaskExecutor@45a37b8c",
        "parent": "<root>",
        "owner": null,
        "threads": [
         {
           "tid": "44",
           "name": "handler-13",
           "stack": [
              "java.base\/java.lang.VirtualThread.parkNanos(VirtualThread.java:621)",
              "java.base\/java.lang.VirtualThread.sleepNanos(VirtualThread.java:793)",
              "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:136)",
              "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)"
           ]
         }
        ],
        "threadCount": "1"
      },
      {
        "container": "ForkJoinPool-1\/jdk.internal.vm.SharedThreadContainer@a5da302",
        "parent": "<root>",
        "owner": null,
        "threads": [
         {
           "tid": "45",
           "name": "ForkJoinPool-1-worker-7",
           "stack": [
              "java.base\/jdk.internal.misc.Unsafe.park(Native Method)",
              "java.base\/java.util.concurrent.locks.LockSupport.parkUntil(LockSupport.java:449)",
              "java.base\/java.util.concurrent.ForkJoinPool.awaitWork(ForkJoinPool.java:1891)",
              "java.base\/java.util.concurrent.ForkJoinPool.runWorker(ForkJoinPool.java:1809)",
              "java.base\/java.util.concurrent.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:188)"
           ]
         }
        ],
        "threadCount": "1"
      },
      {
        "container": "java.util.concurrent.ScheduledThreadPoolExecutor@4d8bd5e9",
        "parent": "<root>",
        "owner": null,
        "threads": [
         {
           "tid": "26",
           "name": "VirtualThread-unparker",
           "stack": [
              "java.base\/jdk.internal.misc.Unsafe.park(Native Method)",
              "java.base\/java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:269)",
              "java.base\/java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:1758)",
              "java.base\/java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1182)",
              "java.base\/java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:899)",
              "java.base\/java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1070)",
              "java.base\/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130)",
              "java.base\/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:642)",
              "java.base\/java.lang.Thread.run(Thread.java:1583)",
              "java.base\/jdk.internal.misc.InnocuousThread.run(InnocuousThread.java:186)"
           ]
         }
        ],
        "threadCount": "1"
      }
    ]
  }
}

あまり面白い結果ではないかもしれませんね…。

CPUを消費する処理。

$ curl localhost:8080/heavy

スレッドダンプ。

{
  "threadDump": {
    "processId": "13711",
    "time": "2023-12-12T14:23:59.202042310Z",
    "runtimeVersion": "21.0.1+12-Ubuntu-222.04",
    "threadContainers": [
      {
        "container": "<root>",
        "parent": null,
        "owner": null,
        "threads": [
         {
           "tid": "9",
           "name": "Reference Handler",
           "stack": [
              "java.base\/java.lang.ref.Reference.waitForReferencePendingList(Native Method)",
              "java.base\/java.lang.ref.Reference.processPendingReferences(Reference.java:246)",
              "java.base\/java.lang.ref.Reference$ReferenceHandler.run(Reference.java:208)"
           ]
         },
         {
           "tid": "10",
           "name": "Finalizer",
           "stack": [
              "java.base\/java.lang.Object.wait0(Native Method)",
              "java.base\/java.lang.Object.wait(Object.java:366)",
              "java.base\/java.lang.Object.wait(Object.java:339)",
              "java.base\/java.lang.ref.NativeReferenceQueue.await(NativeReferenceQueue.java:48)",
              "java.base\/java.lang.ref.ReferenceQueue.remove0(ReferenceQueue.java:158)",
              "java.base\/java.lang.ref.NativeReferenceQueue.remove(NativeReferenceQueue.java:89)",
              "java.base\/java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:173)"
           ]
         },
         {
           "tid": "11",
           "name": "Signal Dispatcher",
           "stack": [
           ]
         },
         {
           "tid": "18",
           "name": "Notification Thread",
           "stack": [
           ]
         },
         {
           "tid": "19",
           "name": "Common-Cleaner",
           "stack": [
              "java.base\/jdk.internal.misc.Unsafe.park(Native Method)",
              "java.base\/java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:269)",
              "java.base\/java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:1847)",
              "java.base\/java.lang.ref.ReferenceQueue.await(ReferenceQueue.java:71)",
              "java.base\/java.lang.ref.ReferenceQueue.remove0(ReferenceQueue.java:143)",
              "java.base\/java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:218)",
              "java.base\/jdk.internal.ref.CleanerImpl.run(CleanerImpl.java:140)",
              "java.base\/java.lang.Thread.run(Thread.java:1583)",
              "java.base\/jdk.internal.misc.InnocuousThread.run(InnocuousThread.java:186)"
           ]
         },
         {
           "tid": "20",
           "name": "idle-timeout-task",
           "stack": [
              "java.base\/java.lang.Object.wait0(Native Method)",
              "java.base\/java.lang.Object.wait(Object.java:366)",
              "java.base\/java.util.TimerThread.mainLoop(Timer.java:563)",
              "java.base\/java.util.TimerThread.run(Timer.java:516)"
           ]
         },
         {
           "tid": "21",
           "name": "HTTP-Dispatcher",
           "stack": [
              "java.base\/sun.nio.ch.EPoll.wait(Native Method)",
              "java.base\/sun.nio.ch.EPollSelectorImpl.doSelect(EPollSelectorImpl.java:121)",
              "java.base\/sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:130)",
              "java.base\/sun.nio.ch.SelectorImpl.select(SelectorImpl.java:142)",
              "jdk.httpserver\/sun.net.httpserver.ServerImpl$Dispatcher.run(ServerImpl.java:474)",
              "java.base\/java.lang.Thread.run(Thread.java:1583)"
           ]
         },
         {
           "tid": "23",
           "name": "DestroyJavaVM",
           "stack": [
           ]
         },
         {
           "tid": "27",
           "name": "Attach Listener",
           "stack": [
              "java.base\/java.lang.Thread.getStackTrace(Thread.java:2450)",
              "java.base\/jdk.internal.vm.ThreadDumper.dumpThreadToJson(ThreadDumper.java:264)",
              "java.base\/jdk.internal.vm.ThreadDumper.dumpThreadsToJson(ThreadDumper.java:237)",
              "java.base\/jdk.internal.vm.ThreadDumper.dumpThreadsToJson(ThreadDumper.java:201)",
              "java.base\/jdk.internal.vm.ThreadDumper.dumpThreadsToFile(ThreadDumper.java:115)",
              "java.base\/jdk.internal.vm.ThreadDumper.dumpThreadsToJson(ThreadDumper.java:84)"
           ]
         }
        ],
        "threadCount": "9"
      },
      {
        "container": "ForkJoinPool.commonPool\/jdk.internal.vm.SharedThreadContainer@7350b626",
        "parent": "<root>",
        "owner": null,
        "threads": [
        ],
        "threadCount": "0"
      },
      {
        "container": "java.util.concurrent.ThreadPoolExecutor@486cc147",
        "parent": "<root>",
        "owner": null,
        "threads": [
        ],
        "threadCount": "0"
      },
      {
        "container": "java.util.concurrent.ThreadPerTaskExecutor@45a37b8c",
        "parent": "<root>",
        "owner": null,
        "threads": [
         {
           "tid": "47",
           "name": "handler-15",
           "stack": [
              "java.base\/java.time.Duration.toMillis(Duration.java:1240)",
              "org.littlewings.virtualthreads.SimpleHttpServer.lambda$createHandler$1(SimpleHttpServer.java:125)",
              "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)"
           ]
         }
        ],
        "threadCount": "1"
      },
      {
        "container": "ForkJoinPool-1\/jdk.internal.vm.SharedThreadContainer@a5da302",
        "parent": "<root>",
        "owner": null,
        "threads": [
         {
           "tid": "48",
           "name": "ForkJoinPool-1-worker-8",
           "stack": [
              "java.base\/jdk.internal.vm.Continuation.run(Continuation.java:248)",
              "java.base\/java.lang.VirtualThread.runContinuation(VirtualThread.java:221)",
              "java.base\/java.util.concurrent.ForkJoinTask$RunnableExecuteAction.exec(ForkJoinTask.java:1423)",
              "java.base\/java.util.concurrent.ForkJoinTask.doExec(ForkJoinTask.java:387)",
              "java.base\/java.util.concurrent.ForkJoinPool$WorkQueue.topLevelExec(ForkJoinPool.java:1312)",
              "java.base\/java.util.concurrent.ForkJoinPool.scan(ForkJoinPool.java:1843)",
              "java.base\/java.util.concurrent.ForkJoinPool.runWorker(ForkJoinPool.java:1808)",
              "java.base\/java.util.concurrent.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:188)"
           ]
         }
        ],
        "threadCount": "1"
      },
      {
        "container": "java.util.concurrent.ScheduledThreadPoolExecutor@4d8bd5e9",
        "parent": "<root>",
        "owner": null,
        "threads": [
         {
           "tid": "26",
           "name": "VirtualThread-unparker",
           "stack": [
              "java.base\/jdk.internal.misc.Unsafe.park(Native Method)",
              "java.base\/java.util.concurrent.locks.LockSupport.park(LockSupport.java:371)",
              "java.base\/java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionNode.block(AbstractQueuedSynchronizer.java:519)",
              "java.base\/java.util.concurrent.ForkJoinPool.unmanagedBlock(ForkJoinPool.java:3780)",
              "java.base\/java.util.concurrent.ForkJoinPool.managedBlock(ForkJoinPool.java:3725)",
              "java.base\/java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:1707)",
              "java.base\/java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1170)",
              "java.base\/java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:899)",
              "java.base\/java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1070)",
              "java.base\/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130)",
              "java.base\/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:642)",
              "java.base\/java.lang.Thread.run(Thread.java:1583)",
              "java.base\/jdk.internal.misc.InnocuousThread.run(InnocuousThread.java:186)"
           ]
         }
        ],
        "threadCount": "1"
      }
    ]
  }
}

スレッドダンプはこれくらいにしておきましょう。

HttpClientでテストしてみる

ここまでの内容を、HttpClientを使ってテストしてみます。

HttpClient (Java SE 21 & JDK 21)

作成したテストはこちら。

src/test/java/org/littlewings/virtualthreads/SimpleHttpServerTest.java

package org.littlewings.virtualthreads;

import org.junit.jupiter.api.AfterEach;
import org.junit.jupiter.api.BeforeEach;
import org.junit.jupiter.api.Test;

import java.net.URI;
import java.net.http.HttpClient;
import java.net.http.HttpRequest;
import java.net.http.HttpResponse;
import java.nio.charset.StandardCharsets;
import java.util.List;
import java.util.concurrent.CompletableFuture;
import java.util.concurrent.ExecutionException;
import java.util.stream.IntStream;

import static org.assertj.core.api.Assertions.assertThat;

class SimpleHttpServerTest {
    static {
        System.setProperty("jdk.virtualThreadScheduler.parallelism", "1");
        System.setProperty("jdk.virtualThreadScheduler.maxPoolSize", "1");
    }

    SimpleHttpServer simpleHttpServer;

    @BeforeEach
    void setUp() {
        simpleHttpServer = SimpleHttpServer.create(18080);
        simpleHttpServer.start();
    }

    @AfterEach
    void tearDown() {
        simpleHttpServer.stop();
    }

    @Test
    void simple() throws InterruptedException, ExecutionException {
        try (HttpClient httpClient = HttpClient.newBuilder().build()) {
            long startTime = 0;
            long elapsedTime = 0;

            // simple
            CompletableFuture<HttpResponse<String>> simpleResponse =
                    httpClient.sendAsync(
                            HttpRequest.newBuilder().uri(URI.create("http://localhost:18080/")).GET().build(),
                            HttpResponse.BodyHandlers.ofString(StandardCharsets.UTF_8)
                    );

            assertThat(simpleResponse.get().body()).isEqualTo("Hello World.");

            // sleep
            startTime = System.currentTimeMillis();

            CompletableFuture<HttpResponse<String>> sleepResponse =
                    httpClient.sendAsync(
                            HttpRequest.newBuilder().uri(URI.create("http://localhost:18080/sleep")).GET().build(),
                            HttpResponse.BodyHandlers.ofString(StandardCharsets.UTF_8)
                    );

            assertThat(sleepResponse.get().body()).isEqualTo("sleep.");

            elapsedTime = System.currentTimeMillis() - startTime;
            assertThat(elapsedTime).isGreaterThan(3000L);

            // cpu heavy
            startTime = System.currentTimeMillis();

            CompletableFuture<HttpResponse<String>> heavyResponse =
                    httpClient.sendAsync(
                            HttpRequest.newBuilder().uri(URI.create("http://localhost:18080/heavy")).GET().build(),
                            HttpResponse.BodyHandlers.ofString(StandardCharsets.UTF_8)
                    );

            assertThat(heavyResponse.get().body()).isEqualTo("heavy.");

            elapsedTime = System.currentTimeMillis() - startTime;
            assertThat(elapsedTime).isGreaterThan(3000L);

            // lock
            startTime = System.currentTimeMillis();

            CompletableFuture<HttpResponse<String>> lockResponse =
                    httpClient.sendAsync(
                            HttpRequest.newBuilder().uri(URI.create("http://localhost:18080/lock")).GET().build(),
                            HttpResponse.BodyHandlers.ofString(StandardCharsets.UTF_8)
                    );

            assertThat(lockResponse.get().body()).isEqualTo("lock.");

            elapsedTime = System.currentTimeMillis() - startTime;
            assertThat(elapsedTime).isGreaterThan(3000L);

            // synchronized lock
            startTime = System.currentTimeMillis();

            CompletableFuture<HttpResponse<String>> synchronizedLockResponse =
                    httpClient.sendAsync(
                            HttpRequest.newBuilder().uri(URI.create("http://localhost:18080/synchronized-lock")).GET().build(),
                            HttpResponse.BodyHandlers.ofString(StandardCharsets.UTF_8)
                    );

            assertThat(synchronizedLockResponse.get().body()).isEqualTo("synchronized lock.");

            elapsedTime = System.currentTimeMillis() - startTime;
            assertThat(elapsedTime).isGreaterThan(3000L);
        }
    }

    @Test
    void concurrentCallSleepEndpoint() throws ExecutionException, InterruptedException {
        try (HttpClient httpClient = HttpClient.newBuilder().build()) {
            long startTime = System.currentTimeMillis();

            List<CompletableFuture<HttpResponse<String>>> responses =
                    IntStream
                            .rangeClosed(1, 3)
                            .mapToObj(i ->
                                    httpClient.sendAsync(
                                            HttpRequest.newBuilder().uri(URI.create("http://localhost:18080/sleep")).GET().build(),
                                            HttpResponse.BodyHandlers.ofString(StandardCharsets.UTF_8)
                                    )
                            )
                            .toList();

            for (CompletableFuture<HttpResponse<String>> response : responses) {
                assertThat(response.get().body()).isEqualTo("sleep.");
            }

            long elapsedTime = System.currentTimeMillis() - startTime;
            assertThat(elapsedTime).isGreaterThan(3000L);
            assertThat(elapsedTime).isLessThan(4000L);
        }
    }

    @Test
    void concurrentCallCpuHeavyEndpoint() throws ExecutionException, InterruptedException {
        try (HttpClient httpClient = HttpClient.newBuilder().build()) {
            long startTime = System.currentTimeMillis();

            List<CompletableFuture<HttpResponse<String>>> responses =
                    IntStream
                            .rangeClosed(1, 3)
                            .mapToObj(i ->
                                    httpClient.sendAsync(
                                            HttpRequest.newBuilder().uri(URI.create("http://localhost:18080/heavy")).GET().build(),
                                            HttpResponse.BodyHandlers.ofString(StandardCharsets.UTF_8)
                                    )
                            )
                            .toList();

            for (CompletableFuture<HttpResponse<String>> response : responses) {
                assertThat(response.get().body()).isEqualTo("heavy.");
            }

            long elapsedTime = System.currentTimeMillis() - startTime;
            assertThat(elapsedTime).isGreaterThan(9000L);
            assertThat(elapsedTime).isLessThan(10000L);
        }
    }

    @Test
    void concurrentCallLockEndpoint() throws ExecutionException, InterruptedException {
        try (HttpClient httpClient = HttpClient.newBuilder().build()) {
            long startTime = System.currentTimeMillis();

            List<CompletableFuture<HttpResponse<String>>> responses =
                    IntStream
                            .rangeClosed(1, 3)
                            .mapToObj(i ->
                                    httpClient.sendAsync(
                                            HttpRequest.newBuilder().uri(URI.create("http://localhost:18080/lock")).GET().build(),
                                            HttpResponse.BodyHandlers.ofString(StandardCharsets.UTF_8)
                                    )
                            )
                            .toList();

            for (CompletableFuture<HttpResponse<String>> response : responses) {
                assertThat(response.get().body()).isEqualTo("lock.");
            }

            long elapsedTime = System.currentTimeMillis() - startTime;
            assertThat(elapsedTime).isGreaterThan(9000L);
            assertThat(elapsedTime).isLessThan(10000L);
        }
    }

    @Test
    void concurrentCallSynchronizedLockEndpoint() throws ExecutionException, InterruptedException {
        try (HttpClient httpClient = HttpClient.newBuilder().build()) {
            long startTime = System.currentTimeMillis();

            List<CompletableFuture<HttpResponse<String>>> responses =
                    IntStream
                            .rangeClosed(1, 3)
                            .mapToObj(i ->
                                    httpClient.sendAsync(
                                            HttpRequest.newBuilder().uri(URI.create("http://localhost:18080/synchronized-lock")).GET().build(),
                                            HttpResponse.BodyHandlers.ofString(StandardCharsets.UTF_8)
                                    )
                            )
                            .toList();

            for (CompletableFuture<HttpResponse<String>> response : responses) {
                assertThat(response.get().body()).isEqualTo("synchronized lock.");
            }

            long elapsedTime = System.currentTimeMillis() - startTime;
            assertThat(elapsedTime).isGreaterThan(9000L);
            assertThat(elapsedTime).isLessThan(10000L);
        }
    }

    @Test
    void concurrentCallLockMixedEndpoint() throws ExecutionException, InterruptedException {
        try (HttpClient httpClient = HttpClient.newBuilder().build()) {
            long startTime = System.currentTimeMillis();

            List<CompletableFuture<HttpResponse<String>>> responses =
                    List.of(
                            httpClient.sendAsync(
                                    HttpRequest.newBuilder().uri(URI.create("http://localhost:18080/lock")).GET().build(),
                                    HttpResponse.BodyHandlers.ofString(StandardCharsets.UTF_8)
                            ),
                            httpClient.sendAsync(
                                    HttpRequest.newBuilder().uri(URI.create("http://localhost:18080/lock2")).GET().build(),
                                    HttpResponse.BodyHandlers.ofString(StandardCharsets.UTF_8)
                            )
                    );

            assertThat(responses.get(0).get().body()).isEqualTo("lock.");
            assertThat(responses.get(1).get().body()).isEqualTo("lock2.");

            long elapsedTime = System.currentTimeMillis() - startTime;
            assertThat(elapsedTime).isGreaterThan(3000L);
            assertThat(elapsedTime).isLessThan(4000L);
        }
    }

    @Test
    void concurrentCallSynchronizedLockMixedEndpoint() throws ExecutionException, InterruptedException {
        try (HttpClient httpClient = HttpClient.newBuilder().build()) {
            long startTime = System.currentTimeMillis();

            List<CompletableFuture<HttpResponse<String>>> responses =
                    List.of(
                            httpClient.sendAsync(
                                    HttpRequest.newBuilder().uri(URI.create("http://localhost:18080/synchronized-lock")).GET().build(),
                                    HttpResponse.BodyHandlers.ofString(StandardCharsets.UTF_8)
                            ),
                            httpClient.sendAsync(
                                    HttpRequest.newBuilder().uri(URI.create("http://localhost:18080/synchronized-lock2")).GET().build(),
                                    HttpResponse.BodyHandlers.ofString(StandardCharsets.UTF_8)
                            )
                    );

            assertThat(responses.get(0).get().body()).isEqualTo("synchronized lock.");
            assertThat(responses.get(1).get().body()).isEqualTo("synchronized lock2.");

            long elapsedTime = System.currentTimeMillis() - startTime;
            assertThat(elapsedTime).isGreaterThan(6000L);
            assertThat(elapsedTime).isLessThan(7000L);
        }
    }
}

テスト開始時にHTTPサーバーを起動し、テスト終了時に停止します。またVirtual Threadsの並列度とプラットフォームスレッド数は1に
しておきます。

    static {
        System.setProperty("jdk.virtualThreadScheduler.parallelism", "1");
        System.setProperty("jdk.virtualThreadScheduler.maxPoolSize", "1");
    }

    SimpleHttpServer simpleHttpServer;

    @BeforeEach
    void setUp() {
        simpleHttpServer = SimpleHttpServer.create(18080);
        simpleHttpServer.start();
    }

    @AfterEach
    void tearDown() {
        simpleHttpServer.stop();
    }

あとは基本的にcurlで確認したことと類似のことをしています。

スリープするエンドポイントに3回並行にアクセスして、レスポンスを受け取るまで3秒ほどなことを確認。

    @Test
    void concurrentCallSleepEndpoint() throws ExecutionException, InterruptedException {
        try (HttpClient httpClient = HttpClient.newBuilder().build()) {
            long startTime = System.currentTimeMillis();

            List<CompletableFuture<HttpResponse<String>>> responses =
                    IntStream
                            .rangeClosed(1, 3)
                            .mapToObj(i ->
                                    httpClient.sendAsync(
                                            HttpRequest.newBuilder().uri(URI.create("http://localhost:18080/sleep")).GET().build(),
                                            HttpResponse.BodyHandlers.ofString(StandardCharsets.UTF_8)
                                    )
                            )
                            .toList();

            for (CompletableFuture<HttpResponse<String>> response : responses) {
                assertThat(response.get().body()).isEqualTo("sleep.");
            }

            long elapsedTime = System.currentTimeMillis() - startTime;
            assertThat(elapsedTime).isGreaterThan(3000L);
            assertThat(elapsedTime).isLessThan(4000L);
        }
    }

異なるロックを取得するReentrantLockを使う場合と、異なるインスタンスに対してsynchronizedでロックを取得すると実行時間に
差が出ること、などですね。

    @Test
    void concurrentCallLockMixedEndpoint() throws ExecutionException, InterruptedException {
        try (HttpClient httpClient = HttpClient.newBuilder().build()) {
            long startTime = System.currentTimeMillis();

            List<CompletableFuture<HttpResponse<String>>> responses =
                    List.of(
                            httpClient.sendAsync(
                                    HttpRequest.newBuilder().uri(URI.create("http://localhost:18080/lock")).GET().build(),
                                    HttpResponse.BodyHandlers.ofString(StandardCharsets.UTF_8)
                            ),
                            httpClient.sendAsync(
                                    HttpRequest.newBuilder().uri(URI.create("http://localhost:18080/lock2")).GET().build(),
                                    HttpResponse.BodyHandlers.ofString(StandardCharsets.UTF_8)
                            )
                    );

            assertThat(responses.get(0).get().body()).isEqualTo("lock.");
            assertThat(responses.get(1).get().body()).isEqualTo("lock2.");

            long elapsedTime = System.currentTimeMillis() - startTime;
            assertThat(elapsedTime).isGreaterThan(3000L);
            assertThat(elapsedTime).isLessThan(4000L);
        }
    }

    @Test
    void concurrentCallSynchronizedLockMixedEndpoint() throws ExecutionException, InterruptedException {
        try (HttpClient httpClient = HttpClient.newBuilder().build()) {
            long startTime = System.currentTimeMillis();

            List<CompletableFuture<HttpResponse<String>>> responses =
                    List.of(
                            httpClient.sendAsync(
                                    HttpRequest.newBuilder().uri(URI.create("http://localhost:18080/synchronized-lock")).GET().build(),
                                    HttpResponse.BodyHandlers.ofString(StandardCharsets.UTF_8)
                            ),
                            httpClient.sendAsync(
                                    HttpRequest.newBuilder().uri(URI.create("http://localhost:18080/synchronized-lock2")).GET().build(),
                                    HttpResponse.BodyHandlers.ofString(StandardCharsets.UTF_8)
                            )
                    );

            assertThat(responses.get(0).get().body()).isEqualTo("synchronized lock.");
            assertThat(responses.get(1).get().body()).isEqualTo("synchronized lock2.");

            long elapsedTime = System.currentTimeMillis() - startTime;
            assertThat(elapsedTime).isGreaterThan(6000L);
            assertThat(elapsedTime).isLessThan(7000L);
        }
    }

ブロッキングなAPI（Socket）を使ったHTTPクライアントとVirtual Threadsの組み合わせを試す

HttpClientは内部でノンブロッキングIOを使っているようです。たとえば、こちら。

https://github.com/openjdk/jdk21u/blob/jdk-21.0.1%2B12/src/java.net.http/share/classes/jdk/internal/net/http/PlainHttpConnection.java

なので、Virtual Threadsを使うのであれば、ブロッキングなAPIを使ってブロックした時に仮想スレッドが切り替わって動作するところを
確認したいものです。

というわけで、最後にjava.net.Socketを使って簡単なHTTPクライアントを作成して、Virtual Threadsと組み合わせて試してみます。

java.net.Socketも書き直されていて、内部的にはVirtual Threadsを使うとノンブロッキングになるようです。

https://github.com/openjdk/jdk21u/blob/jdk-21.0.1%2B12/src/java.base/share/classes/sun/nio/ch/NioSocketImpl.java#L209-L218

APIの使い方は変わらないはずなので、確認ということで。

作成したテストはこちら。

src/test/java/org/littlewings/virtualthreads/BlockingSocketClientTest.java

package org.littlewings.virtualthreads;

import org.junit.jupiter.api.AfterEach;
import org.junit.jupiter.api.BeforeEach;
import org.junit.jupiter.api.Test;

import java.io.*;
import java.net.Socket;
import java.net.URI;
import java.nio.charset.StandardCharsets;
import java.util.List;
import java.util.concurrent.*;
import java.util.stream.IntStream;

import static org.assertj.core.api.Assertions.assertThat;

class BlockingSocketClientTest {
    static {
        // クライアント向け
        System.setProperty("jdk.virtualThreadScheduler.parallelism", "1");
        System.setProperty("jdk.virtualThreadScheduler.maxPoolSize", "1");
    }

    ForkedSimpleHttpServer forkedSimpleHttpServer;

    @BeforeEach
    void setUp() {
        forkedSimpleHttpServer = ForkedSimpleHttpServer.start(28080);
        try {
            TimeUnit.SECONDS.sleep(3L);
        } catch (InterruptedException e) {
            // ignore
        }
    }

    @AfterEach
    void tearDown() {
        forkedSimpleHttpServer.stop();
    }

    // ここに、テストを書く

    static class SimpleHttpClient {
        String get(URI uri) {
            try (Socket socket = new Socket(uri.getHost(), uri.getPort());
                 BufferedWriter writer = new BufferedWriter(new OutputStreamWriter(socket.getOutputStream(), StandardCharsets.UTF_8));
                 BufferedReader reader = new BufferedReader(new InputStreamReader(socket.getInputStream(), StandardCharsets.UTF_8))) {
                writer.write(String.format("GET %s HTTP/1.1", uri.getPath()));
                writer.write("\r\n");
                writer.write(String.format("Host: %s", uri.getHost()));
                writer.write("\r\n");
                writer.write("Connection: close");
                writer.write("\r\n");
                writer.write("\r\n");
                writer.flush();

                String line;

                // skip headers
                while ((line = reader.readLine()) != null) {
                    if (line.isEmpty()) {
                        break;
                    }
                }

                return reader.readLine();
            } catch (IOException e) {
                throw new UncheckedIOException(e);
            }
        }
    }

    static class ForkedSimpleHttpServer {
        private Process process;

        ForkedSimpleHttpServer(Process process) {
            this.process = process;
        }

        static ForkedSimpleHttpServer start(int port) {
            try {
                Process process = new ProcessBuilder().command(List.of(
                        "java",
                        // サーバー側は並列度とスレッド数を増やす
                        "-Djdk.virtualThreadScheduler.parallelism=4",
                        "-Djdk.virtualThreadScheduler.maxPoolSize=4",
                        "-cp",
                        "target/classes",
                        "org.littlewings.virtualthreads.SimpleHttpServer",
                        Integer.toString(port)
                )).start();

                Thread.ofPlatform().daemon(true).start(() -> {
                    try (BufferedReader reader = new BufferedReader(new InputStreamReader(process.getInputStream(), StandardCharsets.UTF_8))) {
                        reader.lines().forEach(System.out::println);
                    } catch (Exception e) {
                        // ignore
                    }
                });

                return new ForkedSimpleHttpServer(process);
            } catch (IOException e) {
                throw new UncheckedIOException(e);
            }
        }

        void stop() {
            process.destroy();
        }
    }
}

Socketを使った自作のHTTPクライアントはこちらです。とりあえずGETメソッドが呼べるだけで、それ以外はなにもできません。

    static class SimpleHttpClient {
        String get(URI uri) {
            try (Socket socket = new Socket(uri.getHost(), uri.getPort());
                 BufferedWriter writer = new BufferedWriter(new OutputStreamWriter(socket.getOutputStream(), StandardCharsets.UTF_8));
                 BufferedReader reader = new BufferedReader(new InputStreamReader(socket.getInputStream(), StandardCharsets.UTF_8))) {
                writer.write(String.format("GET %s HTTP/1.1", uri.getPath()));
                writer.write("\r\n");
                writer.write(String.format("Host: %s", uri.getHost()));
                writer.write("\r\n");
                writer.write("Connection: close");
                writer.write("\r\n");
                writer.write("\r\n");
                writer.flush();

                String line;

                // skip headers
                while ((line = reader.readLine()) != null) {
                    if (line.isEmpty()) {
                        break;
                    }
                }

                return reader.readLine();
            } catch (IOException e) {
                throw new UncheckedIOException(e);
            }
        }
    }

Virtual Threadsの並列度とプラットフォームスレッド数は1にするのですが、これはクライアント向けにします。1であっても、
ブロッキング操作であれば仮想スレッドがアンマウントされて別の仮想スレッドで動くはずですからね。

    static {
        // クライアント向け
        System.setProperty("jdk.virtualThreadScheduler.parallelism", "1");
        System.setProperty("jdk.virtualThreadScheduler.maxPoolSize", "1");
    }

そして、このシステムプロパティの影響をHTTPサーバー側が受けないようにHTTPサーバーは別プロセスで起動するようにしました。
並列度およびプラットフォームスレッド数も多く割り当てています。

    ForkedSimpleHttpServer forkedSimpleHttpServer;

    @BeforeEach
    void setUp() {
        forkedSimpleHttpServer = ForkedSimpleHttpServer.start(28080);
        try {
            TimeUnit.SECONDS.sleep(3L);
        } catch (InterruptedException e) {
            // ignore
        }
    }

    @AfterEach
    void tearDown() {
        forkedSimpleHttpServer.stop();
    }


    static class ForkedSimpleHttpServer {
        private Process process;

        ForkedSimpleHttpServer(Process process) {
            this.process = process;
        }

        static ForkedSimpleHttpServer start(int port) {
            try {
                Process process = new ProcessBuilder().command(List.of(
                        "java",
                        // サーバー側は並列度とスレッド数を増やす
                        "-Djdk.virtualThreadScheduler.parallelism=4",
                        "-Djdk.virtualThreadScheduler.maxPoolSize=4",
                        "-cp",
                        "target/classes",
                        "org.littlewings.virtualthreads.SimpleHttpServer",
                        Integer.toString(port)
                )).start();

                Thread.ofPlatform().daemon(true).start(() -> {
                    try (BufferedReader reader = new BufferedReader(new InputStreamReader(process.getInputStream(), StandardCharsets.UTF_8))) {
                        reader.lines().forEach(System.out::println);
                    } catch (Exception e) {
                        // ignore
                    }
                });

                return new ForkedSimpleHttpServer(process);
            } catch (IOException e) {
                throw new UncheckedIOException(e);
            }
        }

        void stop() {
            process.destroy();
        }
    }

簡単にテスト。

    @Test
    void simple() {
        SimpleHttpClient simpleHttpClient = new SimpleHttpClient();

        String simple = simpleHttpClient.get(URI.create("http://localhost:28080/"));
        assertThat(simple).isEqualTo("Hello World.");

        String sleep = simpleHttpClient.get(URI.create("http://localhost:28080/sleep"));
        assertThat(sleep).isEqualTo("sleep.");

        String heavy = simpleHttpClient.get(URI.create("http://localhost:28080/heavy"));
        assertThat(heavy).isEqualTo("heavy.");

        String lock = simpleHttpClient.get(URI.create("http://localhost:28080/lock"));
        assertThat(lock).isEqualTo("lock.");

        String synchronizedLock = simpleHttpClient.get(URI.create("http://localhost:28080/synchronized-lock"));
        assertThat(synchronizedLock).isEqualTo("synchronized lock.");
    }

Virtual Threads（Executors#newVirtualThreadPerTaskExecutor）を使った並行アクセス。スリープさせてみます。

    @Test
    void concurrentCallSleepEndpoint() throws ExecutionException, InterruptedException {
        ExecutorService es = Executors.newVirtualThreadPerTaskExecutor();

        SimpleHttpClient simpleHttpClient = new SimpleHttpClient();

        long startTime = System.currentTimeMillis();

        List<Future<String>> futures =
                IntStream
                        .rangeClosed(1, 3)
                        .mapToObj(i -> es.submit(() -> simpleHttpClient.get(URI.create("http://localhost:28080/sleep"))))
                        .toList();

        for (Future<String> future : futures) {
            assertThat(future.get()).isEqualTo("sleep.");
        }

        long elapsedTime = System.currentTimeMillis() - startTime;
        assertThat(elapsedTime).isGreaterThan(3000L);
        assertThat(elapsedTime).isLessThan(4000L);
    }

次に、CPUを消費する/heavy。これは、HTTPサーバー側の並列度とプラットフォームスレッド数を上げているので、その分
リクエストを同時に処理できるようになっています。

    @Test
    void concurrentCallCpuHeavyEndpoint() throws ExecutionException, InterruptedException {
        ExecutorService es = Executors.newVirtualThreadPerTaskExecutor();

        SimpleHttpClient simpleHttpClient = new SimpleHttpClient();

        long startTime = System.currentTimeMillis();

        List<Future<String>> futures =
                IntStream
                        .rangeClosed(1, 3)
                        .mapToObj(i -> es.submit(() -> simpleHttpClient.get(URI.create("http://localhost:28080/heavy"))))
                        .toList();

        for (Future<String> future : futures) {
            assertThat(future.get()).isEqualTo("heavy.");
        }

        long elapsedTime = System.currentTimeMillis() - startTime;
        assertThat(elapsedTime).isGreaterThan(3000L);
        assertThat(elapsedTime).isLessThan(4000L);
    }

同じインスタンスに対するロックを取得するものについては、当然ながらアクセスも直列になります。

    @Test
    void concurrentCallLockEndpoint() throws ExecutionException, InterruptedException {
        ExecutorService es = Executors.newVirtualThreadPerTaskExecutor();

        SimpleHttpClient simpleHttpClient = new SimpleHttpClient();

        long startTime = System.currentTimeMillis();

        List<Future<String>> futures =
                IntStream
                        .rangeClosed(1, 3)
                        .mapToObj(i -> es.submit(() -> simpleHttpClient.get(URI.create("http://localhost:28080/lock"))))
                        .toList();

        for (Future<String> future : futures) {
            assertThat(future.get()).isEqualTo("lock.");
        }

        long elapsedTime = System.currentTimeMillis() - startTime;
        assertThat(elapsedTime).isGreaterThan(9000L);
        assertThat(elapsedTime).isLessThan(10000L);
    }

    @Test
    void concurrentCallSynchronizedLockEndpoint() throws ExecutionException, InterruptedException {
        ExecutorService es = Executors.newVirtualThreadPerTaskExecutor();

        SimpleHttpClient simpleHttpClient = new SimpleHttpClient();

        long startTime = System.currentTimeMillis();

        List<Future<String>> futures =
                IntStream
                        .rangeClosed(1, 3)
                        .mapToObj(i -> es.submit(() -> simpleHttpClient.get(URI.create("http://localhost:28080/synchronized-lock"))))
                        .toList();

        for (Future<String> future : futures) {
            assertThat(future.get()).isEqualTo("synchronized lock.");
        }

        long elapsedTime = System.currentTimeMillis() - startTime;
        assertThat(elapsedTime).isGreaterThan(9000L);
        assertThat(elapsedTime).isLessThan(10000L);
    }

ロック対象のインスタンスが変われば、HTTPサーバー側はスレッド数分だけは並列に動けるようになるので、クライアント側の
並列度およびプラットフォームスレッド数が1でもうまく切り替えられるようになっています。

よって、synchoronizedブロックを使う処理にアクセスしても並列に動作するようになりました。もっとも、CPU数分が上限ですが。

    @Test
    void concurrentCallLockMixedEndpoint() throws ExecutionException, InterruptedException {
        ExecutorService es = Executors.newVirtualThreadPerTaskExecutor();

        SimpleHttpClient simpleHttpClient = new SimpleHttpClient();

        long startTime = System.currentTimeMillis();

        List<Future<String>> futures =
                IntStream
                        .rangeClosed(1, 2)
                        .mapToObj(i -> switch (i) {
                            case 1 -> es.submit(() -> simpleHttpClient.get(URI.create("http://localhost:28080/lock")));
                            case 2 -> es.submit(() -> simpleHttpClient.get(URI.create("http://localhost:28080/lock2")));
                            default -> throw new IllegalArgumentException();
                        })
                        .toList();

        assertThat(futures.get(0).get()).isEqualTo("lock.");
        assertThat(futures.get(1).get()).isEqualTo("lock2.");

        long elapsedTime = System.currentTimeMillis() - startTime;
        assertThat(elapsedTime).isGreaterThan(3000L);
        assertThat(elapsedTime).isLessThan(4000L);
    }

    @Test
    void concurrentCallSynchronizedLockMixedEndpoint() throws ExecutionException, InterruptedException {
        ExecutorService es = Executors.newVirtualThreadPerTaskExecutor();

        SimpleHttpClient simpleHttpClient = new SimpleHttpClient();

        long startTime = System.currentTimeMillis();

        List<Future<String>> futures =
                IntStream
                        .rangeClosed(1, 2)
                        .mapToObj(i -> switch (i) {
                            case 1 ->
                                    es.submit(() -> simpleHttpClient.get(URI.create("http://localhost:28080/synchronized-lock")));
                            case 2 ->
                                    es.submit(() -> simpleHttpClient.get(URI.create("http://localhost:28080/synchronized-lock2")));
                            default -> throw new IllegalArgumentException();
                        })
                        .toList();

        assertThat(futures.get(0).get()).isEqualTo("synchronized lock.");
        assertThat(futures.get(1).get()).isEqualTo("synchronized lock2.");

        long elapsedTime = System.currentTimeMillis() - startTime;
        assertThat(elapsedTime).isGreaterThan(3000L);
        assertThat(elapsedTime).isLessThan(4000L);
    }

    @Test
    void concurrentCallAllMixedEndpoint() throws ExecutionException, InterruptedException {
        ExecutorService es = Executors.newVirtualThreadPerTaskExecutor();

        SimpleHttpClient simpleHttpClient = new SimpleHttpClient();

        long startTime = System.currentTimeMillis();

        List<Future<String>> futures =
                IntStream
                        .rangeClosed(1, 6)
                        .mapToObj(i -> switch (i) {
                            case 1 -> es.submit(() -> simpleHttpClient.get(URI.create("http://localhost:28080/sleep")));
                            case 2 -> es.submit(() -> simpleHttpClient.get(URI.create("http://localhost:28080/heavy")));
                            case 3 -> es.submit(() -> simpleHttpClient.get(URI.create("http://localhost:28080/lock")));
                            case 4 -> es.submit(() -> simpleHttpClient.get(URI.create("http://localhost:28080/lock2")));
                            case 5 ->
                                    es.submit(() -> simpleHttpClient.get(URI.create("http://localhost:28080/synchronized-lock")));
                            case 6 ->
                                    es.submit(() -> simpleHttpClient.get(URI.create("http://localhost:28080/synchronized-lock2")));
                            default -> throw new IllegalArgumentException();
                        })
                        .toList();

        assertThat(futures.get(0).get()).isEqualTo("sleep.");
        assertThat(futures.get(1).get()).isEqualTo("heavy.");
        assertThat(futures.get(2).get()).isEqualTo("lock.");
        assertThat(futures.get(3).get()).isEqualTo("lock2.");
        assertThat(futures.get(4).get()).isEqualTo("synchronized lock.");
        assertThat(futures.get(5).get()).isEqualTo("synchronized lock2.");

        long elapsedTime = System.currentTimeMillis() - startTime;
        assertThat(elapsedTime).isGreaterThan(3000L);
        assertThat(elapsedTime).isLessThan(4000L);
    }

OKそうですね。

これでやりたいことはひととおり確認できました。

おわりに

Virtual Threadsの確認ということで、HTTPサーバーおよびクライアントを書いて試してみました。

ブロックする処理で仮想スレッドが切り替わることや、synchronizedを使うとアンマウントできなくなること、そして新しい
スレッドダンプの形式も確認できましたのでVirtual Threadsに対する理解が進んだかなと思います。

これからVirtual Threadsを使っていくかどうかはまだわかりませんが、基礎的な内容として押さえておこうと思います。