CLOVER🍀

That was when it all began.

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

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

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

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

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

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

Virtual Threadsのpinning(ピン留め)

JEP 444(Virtual Threads)についてはこちら。

JEP 444: Virtual Threads

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

環境

今回の環境はこちら。

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


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

準備

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

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

ソースコードはこちら。

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

package org.littlewings.virtualthreads;

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

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

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

    private HttpServer httpServer;

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

            Duration sleepTime = Duration.ofSeconds(3L);

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

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

                        long elapsedTime = System.currentTimeMillis() - startTime;

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

確認してみる

まずはコンパイル

$ mvn compile

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

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

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

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

-Djdk.tracePinnedThreads=full

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

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

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

/sleep

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

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


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

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

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

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

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


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

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

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

/lock

ReentrantLockを使う/lock

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


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

ログ。

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

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

/synchronized-lock

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

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


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

ログはこうなりました。

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

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

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

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

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

-Djdk.tracePinnedThreads=short

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

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

/synchronized-lock

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

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


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

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

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

確かにshortです。

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

もう少し

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

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

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

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

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

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

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

    private static final int TRACE_PINNING_MODE = tracePinningMode();

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

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

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

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

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

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

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

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

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

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

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

        return res == 0;
    }

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

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

        int res = doYield();

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

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

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

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

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

Coninuation#pinnedReasonの内容はこちら。

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

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

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

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

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

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

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

        // find the closest frame that is causing the thread to be pinned
        stack.stream()
            .filter(f -> (f.isNativeMethod() || f.getMonitors().length > 0))
            .map(LiveStackFrame::getDeclaringClass)
            .findFirst()
            .ifPresentOrElse(klass -> {
                int hash = hash(stack);
                Hashes hashes = HASHES.get(klass);
                synchronized (hashes) {
                    // print the stack trace if not already seen
                    if (hashes.add(hash)) {
                        printStackTrace(stack, out, printAll);
                    }
                }
            }, () -> printStackTrace(stack, out, true));  // not found
    }
スタックトレースが1度しか出力されなかったのは?

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

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

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

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

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

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

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

おわりに

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

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

systemdのユニット定義ファイルを確認するにはsystemctl catコマンド、編集するにはsystemctl editコマンドを使う

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

systemdのユニット定義ファイルを編集する際に、ふつうにエディタコマンドで直接開いて設定したりしていたのですが、そのあたりの
考え方が間違ってそうなのでメモしておくことにしました。

systemctl editコマンドで編集するのが良さそうです。

使用するコマンド

systemctlのmanページはこちら。

Ubuntu Manpage: systemctl - Control the systemd system and service manager

今回扱う用途とコマンドの対応表を、以下に記載します。

用途 対応するコマンド 備考
ユニット定義ファイルの内容を確認したい systemctl cat [パターン(ユニット名)] フラグメントやドロップインも含めて表示する
ユニット定義ファイルを編集したい(ドロップイン) systemctrl edit [ユニット名] ドロップインファイルを作成、編集する
ユニット定義ファイルを編集したい(本体) systemctrl edit --full [ユニット名]
ユニット定義ファイルを新規作成したい systemctrl edit --force --full [ユニット名]
ユニット定義ファイルをベンダー定義のバージョンに戻したい systemctl revert [ユニット名] ドロップインファイルは削除される

気にした方がよさそうなポイントもあるのですが、それはこれから見ていきます。

環境

今回の環境は、こちら。

$ lsb_release -a
No LSB modules are available.
Distributor ID: Ubuntu
Description:    Ubuntu 22.04.4 LTS
Release:        22.04
Codename:       jammy


$ uname -smvrpio
Linux 5.15.0-101-generic #111-Ubuntu SMP Tue Mar 5 20:16:58 UTC 2024 x86_64 x86_64 x86_64 GNU/Linux

Ubuntu Linux 22.04 LTSです。

また、お題の都合上Dockerを使用します。

$ docker version
Client: Docker Engine - Community
 Version:           26.0.0
 API version:       1.45
 Go version:        go1.21.8
 Git commit:        2ae903e
 Built:             Wed Mar 20 15:17:48 2024
 OS/Arch:           linux/amd64
 Context:           default

Server: Docker Engine - Community
 Engine:
  Version:          26.0.0
  API version:      1.45 (minimum version 1.24)
  Go version:       go1.21.8
  Git commit:       8b79278
  Built:            Wed Mar 20 15:17:48 2024
  OS/Arch:          linux/amd64
  Experimental:     false
 containerd:
  Version:          1.6.28
  GitCommit:        ae07eda36dd25f8a1b98dfbf587313b99c0190bb
 runc:
  Version:          1.1.12
  GitCommit:        v1.1.12-0-g51d5e94
 docker-init:
  Version:          0.19.0
  GitCommit:        de40ad0

お題

Ubuntu Linux 22.04 LTSにインストールしたDockerに対して、環境変数でプロキシを設定する、というお題でやってみたいと思います。

なお、プロキシサーバーについては省略しますが、http://localhost:8080でアクセスできるものとします。

systemdのユニット定義ファイルを確認する(本体のファイルのみ)

systemdのユニット定義ファイルは、systemctl cat [ユニット名]コマンドで確認できます。管理者権限は不要です。

$ systemctl cat docker
# /lib/systemd/system/docker.service
[Unit]
Description=Docker Application Container Engine
Documentation=https://docs.docker.com
After=network-online.target docker.socket firewalld.service containerd.service time-set.target
Wants=network-online.target containerd.service
Requires=docker.socket

[Service]
Type=notify
# the default is not to use systemd for cgroups because the delegate issues still
# exists and systemd currently does not support the cgroup feature set required
# for containers run by docker
ExecStart=/usr/bin/dockerd -H fd:// --containerd=/run/containerd/containerd.sock
ExecReload=/bin/kill -s HUP $MAINPID
TimeoutStartSec=0
RestartSec=2
Restart=always

# Note that StartLimit* options were moved from "Service" to "Unit" in systemd 229.
# Both the old, and new location are accepted by systemd 229 and up, so using the old location
# to make them work for either version of systemd.
StartLimitBurst=3

# Note that StartLimitInterval was renamed to StartLimitIntervalSec in systemd 230.
# Both the old, and new name are accepted by systemd 230 and up, so using the old name to make
# this option work for either version of systemd.
StartLimitInterval=60s

# Having non-zero Limit*s causes performance problems due to accounting overhead
# in the kernel. We recommend using cgroups to do container-local accounting.
LimitNPROC=infinity
LimitCORE=infinity

# Comment TasksMax if your systemd version does not support it.
# Only systemd 226 and above support this option.
TasksMax=infinity

# set delegate yes so that systemd does not reset the cgroups of docker containers
Delegate=yes

# kill only the docker process, not all processes in the cgroup
KillMode=process
OOMScoreAdjust=-500

[Install]
WantedBy=multi-user.target

コメントで、ユニット定義ファイルのパスが書かれています。

# /lib/systemd/system/docker.service

diffをとってみると、このコメント以外は内容は同じです。

$ diff <(systemctl cat docker) /lib/systemd/system/docker.service
1d0
< # /lib/systemd/system/docker.service

systemdのユニット定義ファイルを編集する(ドロップインファイル)

次に、systemdのユニット定義ファイルを編集してみます。

この時、ソフトウェアの提供元のユニット定義ファイルを直接編集するのではなく、ドロップインファイルでオーバーライドするのが良いと
されています。

ドロップインファイルというのは、ユニット定義がfoo.serviceだった場合にfoo.service.dディレクトリ配下に配置したファイルです。

これは、systemctl edit [ユニット名]で行います。

$ sudo systemctl edit docker

ちなみに、この時Ubuntu Linux 22.04 LTSだとnanoが起動して困ったので、気になる人は以下のコマンドで好みのエディターを指定するように
してください。

$ sudo update-alternatives --config editor

systemctl editを実行すると、以下のようにコメントアウトされた元の内容が表示されるので、こちらを参考にドロップインファイルを
作成しましょう。

### Editing /etc/systemd/system/docker.service.d/override.conf
### Anything between here and the comment below will become the new contents of the file



### Lines below this comment will be discarded

### /lib/systemd/system/docker.service
# [Unit]
# Description=Docker Application Container Engine
# Documentation=https://docs.docker.com
# After=network-online.target docker.socket firewalld.service containerd.service time-set.target
# Wants=network-online.target containerd.service
# Requires=docker.socket
#
# [Service]
〜省略〜

今回は、こんな感じのファイルにしました。

[Service]
Environment="http_proxy=http://localhost:8080"
Environment="https_proxy=http://localhost:8080"

ファイル名は、デフォルトでoverride.confになります。今回は/etc/systemd/system/docker.service.d/override.confになりました。

あとは再起動すれば変更が反映されます。

$ sudo systemctl restart docker

ここで、systemctl editの後にsystemctl daemon-reload要りません

この意味でも、systemctl editを使うべきな気がしますね…。

systemdのユニット定義ファイルを確認する(本体のファイル+ドロップインファイル)

この状態で、systemctl catで確認してみます。

$ systemctl cat docker

ドロップインファイル含めて表示されています。

# /lib/systemd/system/docker.service
[Unit]
Description=Docker Application Container Engine
Documentation=https://docs.docker.com
After=network-online.target docker.socket firewalld.service containerd.service time-set.target
Wants=network-online.target containerd.service
Requires=docker.socket

[Service]
Type=notify
# the default is not to use systemd for cgroups because the delegate issues still
# exists and systemd currently does not support the cgroup feature set required
# for containers run by docker
ExecStart=/usr/bin/dockerd -H fd:// --containerd=/run/containerd/containerd.sock
ExecReload=/bin/kill -s HUP $MAINPID
TimeoutStartSec=0
RestartSec=2
Restart=always

# Note that StartLimit* options were moved from "Service" to "Unit" in systemd 229.
# Both the old, and new location are accepted by systemd 229 and up, so using the old location
# to make them work for either version of systemd.
StartLimitBurst=3

# Note that StartLimitInterval was renamed to StartLimitIntervalSec in systemd 230.
# Both the old, and new name are accepted by systemd 230 and up, so using the old name to make
# this option work for either version of systemd.
StartLimitInterval=60s

# Having non-zero Limit*s causes performance problems due to accounting overhead
# in the kernel. We recommend using cgroups to do container-local accounting.
LimitNPROC=infinity
LimitCORE=infinity

# Comment TasksMax if your systemd version does not support it.
# Only systemd 226 and above support this option.
TasksMax=infinity

# set delegate yes so that systemd does not reset the cgroups of docker containers
Delegate=yes

# kill only the docker process, not all processes in the cgroup
KillMode=process
OOMScoreAdjust=-500

[Install]
WantedBy=multi-user.target

# /etc/systemd/system/docker.service.d/override.conf
[Service]
Environment="http_proxy=http://localhost:8080"
Environment="https_proxy=http://localhost:8080"

本体のユニット定義ファイルを編集する

次は、本体のユニット定義ファイルを編集してみます。

まずsystemctl editでドロップインファイルを以下のように変更。

/etc/systemd/system/docker.service.d/override.conf

[Service]
Environment="http_proxy=http://localhost:8080"
#Environment="https_proxy=http://localhost:8080"

コメントアウトした方は、本体のユニット定義ファイルに追加することにしましょう。

この場合に使うコマンドは、systemctl edit --fullです。

$ sudo systemctl edit --full docker

--fullオプションを付けると、本体のユニット定義ファイルを編集できます。今回は、以下のように変更。

〜省略〜

[Service]
Type=notify
# the default is not to use systemd for cgroups because the delegate issues still
# exists and systemd currently does not support the cgroup feature set required
# for containers run by docker
ExecStart=/usr/bin/dockerd -H fd:// --containerd=/run/containerd/containerd.sock
ExecReload=/bin/kill -s HUP $MAINPID
TimeoutStartSec=0
RestartSec=2
Restart=always
Environment="https_proxy=http://localhost:8080"

〜省略〜

あとは再起動すれば変更が反映されます。

$ sudo systemctl restart docker

変更内容を元に戻す

ここまでで、インストール時点のユニット定義ファイルとは、このような差になりました。

$ diff <(systemctl cat docker) /lib/systemd/system/docker.service
1d0
< # /etc/systemd/system/docker.service
18a18
> Environment="http_proxy=http://localhost:8080"
49,53d48
<
< # /etc/systemd/system/docker.service.d/override.conf
< [Service]
< Environment="http_proxy=http://localhost:8080"
< #Environment="https_proxy=http://localhost:8080"

これを元に戻すには、systemctl revertを実行します。

$ sudo systemctl revert docker

実行ログ。

Removed /etc/systemd/system/docker.service.d/override.conf.
Removed /etc/systemd/system/docker.service.d.
Removed /etc/systemd/system/docker.service.

差分がなくなりました。

$ diff <(systemctl cat docker) /lib/systemd/system/docker.service
1d0
< # /lib/systemd/system/docker.service

新しくユニット定義ファイルを作成する

systemctlコマンドで新しくユニット定義ファイルを作成する場合は、systemctl edit --force --fullコマンドを使います。

$ sudo systemctl edit --force --full my-service

この場合、/etc/systemd/system配下にファイルを作成しようとします。

自分で用意したユニット定義ファイルをrevertすると?

ところで、自分で用意したユニット定義ファイルをsystemctl revertするとどうなるのでしょう?

作成してみます。

$ sudo systemctl edit --force --full my-httpd

こんな内容にしてみました。

$ systemctl cat my-httpd
# /etc/systemd/system/my-httpd.service
[Unit]
Description=My Simple Http Server
After=networ-online.target
Wants=network-online.target

[Service]
Type=simple
ExecStart=python3 -m http.server --directory /tmp

[Install]
WantedBy=multi-user.target

起動することを確認。

$ sudo systemctl start my-httpd

systemctl revertしてみます。

$ sudo systemctl revert my-httpd

特になにも表示されません。systemctl catでも、そのまま中身が残っています。

$ systemctl cat my-httpd
# /etc/systemd/system/my-httpd.service
[Unit]
Description=My Simple Http Server
After=networ-online.target
Wants=network-online.target

[Service]
Type=simple
ExecStart=python3 -m http.server --directory /tmp

[Install]
WantedBy=multi-user.target

それもそのはずで、manページを見ると「削除されない」と書かれています。

Note that if a unit file has no vendor-supplied version (i.e. is only defined below /etc/systemd/system or /run/systemd/system, but not in a unit file stored below /usr/), then it is not removed. Also, if a unit is masked, it is unmasked.

Ubuntu Manpage: systemctl - Control the systemd system and service manager

ちなみに、自分で用意したユニット定義ファイルにもsystemctl editでドロップインファイルを作成することができます。
このパターンはあまり使わない気もしますが。

おわりに

systemdのユニット定義ファイルを確認、編集、そしてインストールした時点のものに戻す方法を調べてみました。

今までふつうにエディターで編集していたので、こうやってコマンドで操作できることを知りませんでした…。
コマンドのmanページとか見ないとダメですね…。