CLOVER🍀

That was when it all began.

Fakerでフェイクデータを作成する

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

Qdrantのドキュメントを見ていて、Fakerというフェイクデータを生成するライブラリーがあることを知ったので簡単に試しておきます。

Faker

FakerのWebサイト、GitHubリポジトリーはこちら。

Welcome to Faker’s documentation! — Faker 24.4.0 documentation

GitHub - joke2k/faker: Faker is a Python package that generates fake data for you.

Fakerはフェイクデータを作成するライブラリーで、データベースのセットアップや性能テスト、匿名化したデータの作成といった用途で
利用することが想定されています。

今回はPythonのFakerを扱うのですが、複数の言語で存在するようです。

PHPのFakerのリポジトリーはアーカイブされていました。

GitHub - fzaninotto/Faker: Faker is a PHP library that generates fake data for you

ここからはPython版のFakerを見ていきます。

使い方はこんな感じで、Fakerのインスタンスを作成した後にフェイクデータに対応するメソッドを呼び出すようです。

from faker import Faker
fake = Faker()

fake.name()
# 'Lucy Cechtelar'

fake.address()
# '426 Jordy Lodge
#  Cartwrightshire, SC 88120-6700'

fake.text()
# 'Sint velit eveniet. Rerum atque repellat voluptatem quia rerum. Numquam excepturi
#  beatae sint laudantium consequatur. Magni occaecati itaque sint et sit tempore. Nesciunt
#  amet quidem. Iusto deleniti cum autem ad quia aperiam.
#  A consectetur quos aliquam. In iste aliquid et aut similique suscipit. Consequatur qui
#  quaerat iste minus hic expedita. Consequuntur error magni et laboriosam. Aut aspernatur
#  voluptatem sit aliquam. Dolores voluptatum est.
#  Aut molestias et maxime. Fugit autem facilis quos vero. Eius quibusdam possimus est.
#  Ea quaerat et quisquam. Deleniti sunt quam. Adipisci consequatur id in occaecati.
#  Et sint et. Ut ducimus quod nemo ab voluptatum.'

これらのメソッド(上記例だとnameやaddress、text)のことは"fake"と呼ばれ、"fake"の多くはプロバイダーとしてパッケージされている
ようです。

プロバイダーのリストはこちら。

Standard Providers — Faker 24.4.0 documentation

コミュニティによるプロバイダーもあるようです。

Community Providers — Faker 24.4.0 documentation

また、自分でプロバイダーを作成したり、カスタマイズしたりすることもできるようです。

ローカライズにも対応しているようです。ja_JPで、日本語のフェイクデータが生成できそうです。

from faker import Faker
fake = Faker(['it_IT', 'en_US', 'ja_JP'])
for _ in range(10):
    print(fake.name())

# 鈴木 陽一
# Leslie Moreno
# Emma Williams
# 渡辺 裕美子
# Marcantonio Galuppi
# Martha Davis
# Kristen Turner
# 中津川 春香
# Ashley Castillo
# 山田 桃子

Localization

コマンドラインツールとしても使えます。

Command line usage

紹介はこれくらいにして、使っていってみましょう。

環境

今回の環境はこちら。

$ python3 --version
Python 3.10.12


$ pip3 --version
pip 22.0.2 from /usr/lib/python3/dist-packages/pip (python 3.10)

Fakerを使ってみる

それでは、Fakerを使ってみましょう。

まずはインストール。

$ pip3 install Faker

現在のバージョンは24.4.0です。

$ pip3 list
Package         Version
--------------- -----------
Faker           24.4.0
pip             22.0.2
python-dateutil 2.9.0.post0
setuptools      59.6.0
six             1.16.0
コマンドラインツールとして使ってみる

最初はコマンドラインツールとして使ってみましょう。

バージョン。

$ faker --version
faker 24.4.0

ヘルプ。

$ faker --help
usage: faker [-h] [--version] [-v] [-o output] [-l LOCALE] [-r REPEAT] [-s SEP] [--seed SEED] [-i [INCLUDE ...]] [fake] [fake argument ...]

faker version 24.4.0

positional arguments:
  fake                  name of the fake to generate output for (e.g. profile)
  fake argument         optional arguments to pass to the fake (e.g. the profile fake takes an optional list of comma separated field names as the first argument)

options:
  -h, --help            show this help message and exit
  --version             show program's version number and exit
  -v, --verbose         show INFO logging events instead of CRITICAL, which is the default. These logging events provide insight into localization of specific providers.
  -o output             redirect output to a file
  -l LOCALE, --lang LOCALE
                        specify the language for a localized provider (e.g. de_DE)
  -r REPEAT, --repeat REPEAT
                        generate the specified number of outputs
  -s SEP, --sep SEP     use the specified separator after each output
  --seed SEED           specify a seed for the random generator so that results are repeatable. Also compatible with 'repeat' option
  -i [INCLUDE ...], --include [INCLUDE ...]
                        list of additional custom providers to user, given as the import path of the module containing your Provider class (not the provider class itself)

supported locales:

  ar_AA, ar_AE, ar_BH, ar_EG, ar_JO, ar_PS, ar_SA, az_AZ, bg_BG, bn_BD, bs_BA, cs_CZ, da_DK, de, de_AT, de_CH, de_DE, dk_DK, el_CY, el_GR, en, en_AU, en_BD, en_CA, en_GB, en_IE, en_IN, en_NZ, en_PH, en_TH, en_US, es, es_AR, es_CA, es_CL, es_CO, es_ES, es_MX, et_EE, fa_IR, fi_FI, fil_PH, fr_BE, fr_CA, fr_CH, fr_FR, fr_QC, ga_IE, he_IL, hi_IN, hr_HR, hu_HU, hy_AM, id_ID, it_CH, it_IT, ja_JP, ka_GE, ko_KR, la, lb_LU, lt_LT, lv_LV, mt_MT, ne_NP, nl_BE, nl_NL, no_NO, or_IN, pl_PL, pt_BR, pt_PT, ro_RO, ru_RU, sk_SK, sl_SI, sq_AL, sv_SE, ta_IN, th, th_TH, tl_PH, tr_TR, tw_GH, uk_UA, vi_VN, zh_CN, zh_TW, zu_ZA

  Faker can take a locale as an optional argument, to return localized data. If
  no locale argument is specified, the factory falls back to the user's OS
  locale as long as it is supported by at least one of the providers.
     - for this user, the default locale is ja_JP.

  If the optional argument locale and/or user's default locale is not available
  for the specified provider, the factory falls back to faker's default locale,
  which is en_US.

examples:

  $ faker address
  968 Bahringer Garden Apt. 722
  Kristinaland, NJ 09890

  $ faker -l de_DE address
  Samira-Niemeier-Allee 56
  94812 Biedenkopf

  $ faker profile ssn,birthdate
  {'ssn': u'628-10-1085', 'birthdate': '2008-03-29'}

  $ faker -r=3 -s=";" name
  Willam Kertzmann;
  Josiah Maggio;
  Gayla Schmitt;

サポートされているLocaleも表示されるんですね。

supported locales:

  ar_AA, ar_AE, ar_BH, ar_EG, ar_JO, ar_PS, ar_SA, az_AZ, bg_BG, bn_BD, bs_BA, cs_CZ, da_DK, de, de_AT, de_CH, de_DE, dk_DK, el_CY, el_GR, en, en_AU, en_BD, en_CA, en_GB, en_IE, en_IN, en_NZ, en_PH, en_TH, en_US, es, es_AR, es_CA, es_CL, es_CO, es_ES, es_MX, et_EE, fa_IR, fi_FI, fil_PH, fr_BE, fr_CA, fr_CH, fr_FR, fr_QC, ga_IE, he_IL, hi_IN, hr_HR, hu_HU, hy_AM, id_ID, it_CH, it_IT, ja_JP, ka_GE, ko_KR, la, lb_LU, lt_LT, lv_LV, mt_MT, ne_NP, nl_BE, nl_NL, no_NO, or_IN, pl_PL, pt_BR, pt_PT, ro_RO, ru_RU, sk_SK, sl_SI, sq_AL, sv_SE, ta_IN, th, th_TH, tl_PH, tr_TR, tw_GH, uk_UA, vi_VN, zh_CN, zh_TW, zu_ZA

たとえば、nameで試してみましょう。

$ faker name
木村 陽一

いきなり日本語が出ました…。

よく見ると、Localeを未指定の場合はOSのLocaleを使うと書かれていますね。

  Faker can take a locale as an optional argument, to return localized data. If
  no locale argument is specified, the factory falls back to the user's OS
  locale as long as it is supported by at least one of the providers.
     - for this user, the default locale is ja_JP.

明示的に指定する場合は-lまたは--langで指定します。

$ faker -l ja_JP name
高橋 聡太郎


$ faker --lang en_US name
Benjamin Shea

今回は明示的に指定することにしましょう。

-rで、指定した回数出力できます。

$ faker -l ja_JP -r 3 address
大阪府大島町上高野10丁目8番13号 パレス湯本塩原922

長野県長生郡白子町四番町6丁目21番6号

佐賀県羽村市北上野36丁目12番3号

-sでセパレーターを指定します。空行が気になるので、空文字にしました。

$ faker -l ja_JP -r 3 -s '' address
京都府我孫子市東神田25丁目13番17号
青森県大田区押上12丁目22番17号
島根県荒川区北上野25丁目25番4号 上吉羽パレス925

-oでファイルに出力できます。

$ faker -l ja_JP -r 10 -s '' -o isbn13-10.txt  isbn13

結果。

isbn13-10.txt

978-0-7743-8714-9
978-1-72817-220-0
978-1-61194-154-8
978-0-9625246-4-6
978-0-344-76991-7
978-0-252-38021-1
978-0-9788212-0-3
978-1-66603-286-4
978-1-9815-2440-2
978-1-103-64848-1

プロバイダーによっては、こういう出力になるものもあります。

$ faker -l ja_JP profile
{'job': '公務員', 'company': '有限会社長谷川保険', 'ssn': '871-33-9808', 'residence': '新潟県八千代市六番町2丁目1番7号 柿木沢新田パーク717', 'current_location': (Decimal('-62.3285515'), Decimal('-22.976681')), 'blood_group': 'O-', 'website': ['https://www.nakamura.com/', 'https://ito.jp/', 'http://nakamura.com/'], 'username': 'fyamaguchi', 'name': '吉田 零', 'sex': 'M', 'address': '長野県青梅市高輪36丁目19番18号 パーク橋場885', 'mail': 'momokokondo@gmail.com', 'birthdate': datetime.date(2018, 6, 29)}

この場合、指定した要素に絞って出力もできます。

$ faker -l ja_JP profile job,company
{'job': '司法書士', 'company': '合同会社松田保険'}

また、プロバイダーによってはプロバイダーをそのまま指定してもダメなものもあります。

## これはNG
$ faker -l ja_JP person
Traceback (most recent call last):
  File "/path/to/site-packages/faker/generator.py", line 92, in get_formatter
    return getattr(self, formatter)
AttributeError: 'Generator' object has no attribute 'person'

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/path/to/site-packages/faker/cli.py", line 97, in print_doc
    print(fake.format(provider_or_field, *args), end="", file=output)
  File "/path/to/site-packages/faker/generator.py", line 88, in format
    return self.get_formatter(formatter)(*args, **kwargs)
  File "/path/to/site-packages/faker/generator.py", line 98, in get_formatter
    raise AttributeError(msg)
AttributeError: Unknown formatter 'person' with locale 'ja_JP'

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/path/to/bin/faker", line 8, in <module>
    sys.exit(execute_from_command_line())
  File "/path/to/site-packages/faker/cli.py", line 291, in execute_from_command_line
    command.execute()
  File "/path/to/site-packages/faker/cli.py", line 265, in execute
    print_doc(
  File "/path/to/site-packages/faker/cli.py", line 99, in print_doc
    raise ValueError(f'No faker found for "{provider_or_field}({args})"')
ValueError: No faker found for "person([])"


## これはOK
$ faker -l ja_JP name
佐藤 涼平

これは、あくまで指定するのはfakeだからです。

nameはpersonプロバイダーのfakeです。プロバイダーとfakeの名前が一致するとは限らないようなので、プロバイダーの一覧
というよりはその中にあるfakeを見た方がよさそうですね。

faker.providers.person — Faker 24.6.0 documentation

コマンドラインツールとしての使い方は、これくらいにしておきましょう。

プログラムで使う

続いて、プログラムで使ってみましょう。

こんな感じで作成。

app.py

from faker import Faker

faker = Faker("ja_JP")

header = ["name", "address", "phone-number", "job"]

print(" | ".join(header))

for _ in range(10):
    print(
        " | ".join([faker.name(), faker.address(), faker.phone_number(), faker.job()])
    )

実行結果。

$ python3 app.py
name | address | phone-number | job
高橋 修平 | 島根県四街道市神明内1丁目7番9号 元浅草コーポ173 | 090-6292-3048 | 音楽家
小林 加奈 | 山口県八王子市上広谷14丁目23番3号 | 73-4556-0885 | 裁判官
山田 浩 | 栃木県稲城市羽折町22丁目19番6号 シャルム西浅草447 | 080-4384-5952 | コピーライター
斎藤 あすか | 大阪府武蔵村山市北上野16丁目1番20号 東浅草アーバン995 | 070-2098-5528 | 電気工事士
池田 篤司 | 宮城県山武郡芝山町箭坪24丁目5番5号 コート戸島217 | 080-9504-4444 | 医師
橋本 千代 | 群馬県山武郡横芝光町上高野35丁目26番8号 上高野コート456 | 65-8558-5395 | モデル
吉田 太一 | 熊本県香取市蟇沼24丁目16番5号 | 080-1606-0085 | 公務員
渡辺 千代 | 長崎県日野市中小来川8丁目3番17号 クレスト一ツ橋795 | 070-7744-8111 | 気象予報士
山田 和也 | 青森県武蔵村山市蔵前26丁目26番16号 | 66-1338-0212 | ゲームクリエイター
高橋 康弘 | 高知県横浜市鶴見区天神島2丁目27番19号 | 18-2240-9622 | 救急救命士

だいたい雰囲気はわかりましたね。

あとはプロバイダーのドキュメントを見ていけばよいかなと思います。

オマケ

ちょっと気になるので、実装を見てみましょう。

プロバイダーは、Localeごとのディレクトリにあるようです。

https://github.com/joke2k/faker/blob/v24.4.0/faker/providers/person/ja_JP/__init__.py

どんなデータが生成されそうなのかは、ソースコードを見ればわかりそうです。

    first_name_female_pairs = (
        ("明美", "アケミ", "Akemi"),
        ("あすか", "アスカ", "Asuka"),
        ("香織", "カオリ", "Kaori"),
        ("加奈", "カナ", "Kana"),
        ("くみ子", "クミコ", "Kumiko"),
        ("さゆり", "サユリ", "Sayuri"),
        ("知実", "サトミ", "Satomi"),
        ("千代", "チヨ", "Chiyo"),
        ("直子", "ナオコ", "Naoko"),
        ("七夏", "ナナミ", "Nanami"),
        ("花子", "ハナコ", "Hanako"),
        ("春香", "ハルカ", "Haruka"),
        ("真綾", "マアヤ", "Maaya"),
        ("舞", "マイ", "Mai"),
        ("美加子", "ミカコ", "Mikako"),
        ("幹", "ミキ", "Miki"),
        ("桃子", "モモコ", "Momoko"),
        ("結衣", "ユイ", "Yui"),
        ("裕美子", "ユミコ", "Yumiko"),
        ("陽子", "ヨウコ", "Yoko"),
        ("里佳", "リカ", "Rika"),
    )

    # for backwards compatibility
    first_names_female = tuple(map(itemgetter(0), first_name_female_pairs))
    first_kana_names_female = tuple(map(itemgetter(1), first_name_female_pairs))
    first_romanized_names_female = tuple(map(itemgetter(2), first_name_female_pairs))

    first_name_male_pairs = (
        ("晃", "アキラ", "Akira"),
        ("篤司", "アツシ", "Atsushi"),
        ("治", "オサム", "Osamu"),
        ("和也", "カズヤ", "Kazuya"),
        ("京助", "キョウスケ", "Kyosuke"),
        ("健一", "ケンイチ", "Kenichi"),
        ("修平", "シュウヘイ", "Shohei"),
        ("翔太", "ショウタ", "Shota"),
        ("淳", "ジュン", "Jun"),
        ("聡太郎", "ソウタロウ", "Sotaro"),
        ("太一", "タイチ", "Taichi"),
        ("太郎", "タロウ", "Taro"),
        ("拓真", "タクマ", "Takuma"),
        ("翼", "ツバサ", "Tsubasa"),
        ("智也", "トモヤ", "Tomoya"),
        ("直樹", "ナオキ", "Naoki"),
        ("直人", "ナオト", "Naoto"),
        ("英樹", "ヒデキ", "Hideki"),
        ("浩", "ヒロシ", "Hiroshi"),
        ("学", "マナブ", "Manabu"),
        ("充", "ミツル", "Mituru"),
        ("稔", "ミノル", "Minoru"),
        ("裕樹", "ユウキ", "Yuki"),
        ("裕太", "ユウタ", "Yuta"),
        ("康弘", "ヤスヒロ", "Yasuhiro"),
        ("陽一", "ヨウイチ", "Yoichi"),
        ("洋介", "ヨウスケ", "Yosuke"),
        ("亮介", "リョウスケ", "Ryosuke"),
        ("涼平", "リョウヘイ", "Ryohei"),
        ("零", "レイ", "Rei"),
    )

    # for backwards compatibility
    first_names_male = tuple(map(itemgetter(0), first_name_male_pairs))
    first_kana_names_male = tuple(map(itemgetter(1), first_name_male_pairs))
    first_romanized_names_male = tuple(map(itemgetter(2), first_name_male_pairs))

    # for backwards compatibility
    first_names = first_names_male + first_names_female
    first_kana_names = first_kana_names_male + first_kana_names_female
    first_romanized_names = first_romanized_names_male + first_romanized_names_female

    first_name_pairs = first_name_male_pairs + first_name_female_pairs

    last_name_pairs = OrderedDict(
        (
            (("佐藤", "サトウ", "Sato"), 366803.0),
            (("鈴木", "スズキ", "Suzuki"), 321135),
            (("高橋", "タカハシ", "Takahashi"), 266782),
            (("田中", "タナカ", "Tanaka"), 245821),
            (("伊藤", "イトウ", "Ito"), 203357),
            (("渡辺", "ワタナベ", "Watanabe"), 200504),
            (("山本", "ヤマモト", "Yamamoto"), 200134),
            (("中村", "ナカムラ", "Nakamura"), 195219),
            (("小林", "コバヤシ", "Kobayashi"), 191819),
            (("加藤", "カトウ", "Kato"), 160283),
            (("吉田", "ヨシダ", "Yoshida"), 154461),
            (("山田", "ヤマダ", "Yamada"), 151675),
            (("佐々木", "ササキ", "Sasaki"), 135927),
            (("山口", "ヤマグチ", "Yamaguchi"), 119501),
            (("松本", "マツモト", "Matsumoto"), 116490),
            (("井上", "イノウエ", "Inoue"), 111287),
            (("木村", "キムラ", "Kimura"), 107446),
            (("林", "ハヤシ", "Hayashi"), 101826),
            (("斎藤", "サイトウ", "Saito"), 101774),
            (("清水", "シミズ", "Shimizu"), 97826),
            (("山崎", "ヤマザキ", "Yamazaki"), 90781),
            (("阿部", "アベ", "Abe"), 86833),
            (("森", "モリ", "Mori"), 86507),
            (("池田", "イケダ", "Ikeda"), 84860),
            (("橋本", "ハシモト", "Hashimoto"), 82836),
            (("山下", "ヤマシタ", "Yamashita"), 80588),
            (("石川", "イシカワ", "Ishikawa"), 77471),
            (("中島", "ナカジマ", "Nakajima"), 74106),
            (("前田", "マエダ", "Maeda"), 72930),
            (("藤田", "フジタ", "Fujita"), 72375),
            (("後藤", "ゴトウ", "Goto"), 71629),
            (("小川", "オガワ", "Ogawa"), 71179),
            (("岡田", "オカダ", "Okada"), 70347),
            (("長谷川", "ハセガワ", "Hasegawa"), 69201),
            (("村上", "ムラカミ", "Murakami"), 68606),
            (("近藤", "コンドウ", "Kondo"), 68297),
            (("石井", "イシイ", "Ishii"), 67079),
            (("遠藤", "エンドウ", "Endo"), 62620),
            (("斉藤", "サイトウ", "Saito"), 62540),
            (("坂本", "サカモト", "Sakamoto"), 62308),
            (("青木", "アオキ", "Aoki"), 59516),
            (("藤井", "フジイ", "Fujii"), 59204),
            (("西村", "ニシムラ", "Nishimura"), 58821),
            (("福田", "フクダ", "Fukuda"), 58714),
            (("太田", "オオタ", "Ota"), 58439),
            (("三浦", "ミウラ", "Miura"), 58006),
            (("藤原", "フジワラ", "Fujiwara"), 57742),
            (("松田", "マツダ", "Matsuda"), 55883),
            (("岡本", "オカモト", "Okamoto"), 55539),
            (("中川", "ナカガワ", "Nakagawa"), 55221),
        )
    )

https://github.com/joke2k/faker/blob/v24.4.0/faker/providers/person/ja_JP/__init__.py#L11-L138

プロバイダーによって、用意されているLocaleには差がありそうなので注意ですね。

たとえばpersonは多いですが

https://github.com/joke2k/faker/tree/v24.4.0/faker/providers/person

barcodeは5つだけです。

https://github.com/joke2k/faker/tree/v24.4.0/faker/providers/barcode

おわりに

フェイクデータを生成するFakerを試してみました。

こういうものがあるのを知らなかったです。複数の言語での実装もあるようですし、便利そうですね。少なくともPython版については
カスタマイズもできそうですし。

覚えておくとよさそうです。

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

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

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

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

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

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

Virtual Threadsのpinning(ピン留め)

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

JEP 444: Virtual Threads

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

環境

今回の環境はこちら。

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


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

準備

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

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

ソースコードはこちら。

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

package org.littlewings.virtualthreads;

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

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

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

    private HttpServer httpServer;

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

            Duration sleepTime = Duration.ofSeconds(3L);

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

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

                        long elapsedTime = System.currentTimeMillis() - startTime;

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

確認してみる

まずはコンパイル。

$ mvn compile

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

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

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

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

-Djdk.tracePinnedThreads=full

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

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

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

/sleep

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

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


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

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

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

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

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


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

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

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

/lock

ReentrantLockを使う/lock。

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


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

ログ。

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

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

/synchronized-lock

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

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


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

ログはこうなりました。

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

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

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

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

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

-Djdk.tracePinnedThreads=short

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

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

/synchronized-lock

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

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


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

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

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

確かにshortです。

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

もう少し

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

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

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

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

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

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

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

    private static final int TRACE_PINNING_MODE = tracePinningMode();

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

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

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

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

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

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

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

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

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

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

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

        return res == 0;
    }

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

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

        int res = doYield();

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

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

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

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

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

Coninuation#pinnedReasonの内容はこちら。

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

おわりに

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

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