JDK 21 サービスの場合、ログは書き込まれなくなり、すべてのインターフェイスがタイムアウトになり、ロックを保持しているユーザーが jstack で見つかりません。最終的に、問題は仮想スレッドのスケジューラにあり、ロック自体とはほとんど関係がないことが判明しました。
現象
テスト環境 (JDK 21、8 コア マシン) に、夜に突然停止したサービスがあります。
- アプリケーション ログはある時点で停止し、13 時間にわたって 1 行も書き込まれませんでした。
- プロセスはまだ存在しており、GC は正常に行われており、arthas は接続できます。
- すべての外部 Dubbo クエリ インターフェイスがタイムアウトになります。
- jstack 内の多くのスレッドが同じスレッド内でスタックしている
ReentrantLockオンですが、ダンプ全体でこのロックを保持している人が見つかりません。
スタックしたスレッドはすべてログを記録しており、スタックの長さは次のとおりです。
at java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:322)
at java.util.concurrent.ArrayBlockingQueue.remainingCapacity(ArrayBlockingQueue.java:485)
at ch.qos.logback.core.AsyncAppenderBase.append(AsyncAppenderBase.java:162)
...
スレッドがログバックで止まっています AsyncAppender 内部キューのロック。ログに記録する必要があるすべてのスレッドはここでキューに入れられます。ビジネス コードが実行できない場合、サービス全体が停止します。
アドバンスポイントの背景
3 つの概念は後ほど使用しますので、最初に説明しましょう。
仮想スレッドを実行するには、キャリア スレッドを借用する必要があります。 仮想スレッドは OS スレッドではないため、実行するにはキャリア スレッドにスケジュールする必要があります。キャリアスレッドの ForkJoinPool ここで、デフォルトの数は CPU コアの数と等しく、8 コアは 8 ストリップを意味します。
ReentrantLock ブロッキングするとキャリアスレッドが放棄されます。synchronized ブロッキングはそうではありません。 仮想スレッドの lock.lock() 待機中はパーキングされ、キャリア スレッドは他の人が使用できるように解放されます。しかし、 synchronized 上級レベル (JDK 21 の実装) では、仮想スレッドはキャリア スレッドに固定され、キャリア スレッドもそれとともにブロックされ、スケジューラは何もすることができません。これがピン留めです。
仮想スレッドになります RUNNABLE実行しているという意味ではありません。 ロックが解除された後は、ReentrantLock ミーティング unpark キューの先頭にあるスレッド。仮想スレッドの場合、unpark それをスケジューラのキューにスローするだけで、実際に実行する前にキャリア スレッドに分割する必要があります。
結論は
| 質問 | 答え |
|---|---|
| どこに詰まっているのでしょうか？ | ログバック AsyncAppender 列に並んだ ReentrantLockステータスは Unlockedしかし、キューには 288 個のスレッドがあります |
| 鍵は空ですが、なぜ誰も開けられないのでしょうか? | チームの先頭にある仮想スレッドは起動されますが、キャリア スレッドに割り当てることができず、ロックを取得するために実行できません。 |
| キャリアスレッドが分離できないのはなぜですか? | 8 つのキャリア スレッドはすべて固定されています。仮想スレッドがあります。 synchronized このログ ロックを待っている間、ログ ロックはキャリア スレッドを占有し、他のスレッドもそれによってブロックされます。 synchronized 外 |
トラブルシューティングのプロセス
ステップ 1: スレッド ダンプでは、ロックを保持しているスレッドが確認できません
最も直接的なアイデアは、ダンプ内でこのロックを誰が保持しているかを見つけることです。最初の Jstack を持ってきませんでした -l無駄に。またベルトを手に入れた -l はい、まだです。
その理由は、jstack が仮想スレッドをリストしないためです。と置き換えます jcmd Thread.dump_to_file 仮想スレッドは見えていますが、今回キャプチャしたjson形式とテキスト形式にはロック情報がありません。
したがって、このシナリオではスレッド ダンプは「誰がロックを保持しているか」を答えることができないため、別の方法を見つける必要があります。
ステップ 2: ロックについて直接質問する
アーサスは反省して読みたいと思っています exclusiveOwnerThreadモジュールのカプセル化によってブロックされています (java.util.concurrent 開いていない --add-opens）。
考え方を変えてください。ReentrantLock.toString() これはパブリックメソッドであり、出力されます [Locked by thread xxx] または [Unlocked]。使用 vmtool 全体を積み上げる ReentrantLock 全体をスキャンして、キューが最も長いものを選択します。
vmtool --action getInstances --className java.util.concurrent.locks.ReentrantLock --limit 999999 \
--express "instances.{? #this.getQueueLength() > 10}.{#this.toString() + ' qlen=' + #this.getQueueLength()}"
結果：
java.util.concurrent.locks.ReentrantLock@7ced673d[Unlocked] qlen=288
山全体は 27221 です ReentrantLockこれは 10 個を超えるキューがある唯一のキューであり、ロック解除されています。誰もロックを保持していませんが、288 個のスレッドがキューに入れられています。これは奇妙だ。
ステップ 3: キャリア スレッドが不足していると疑う
ロックは空で、キュー内に多数の仮想スレッドがあります。私は 2 つの可能性を考えています。
- キューの先頭にある仮想スレッドは
unparkしかし、キャリアスレッドを待つことができず、ロックを取得できませんでした。 - キャリアスレッドは
synchronizedねじが固定されている
まず、仮想スレッドのステータスを確認します。同じバッチのタスクに対して 614 の仮想スレッド:
| 州 | 量 | 割合 |
|---|---|---|
| 実行可能 | 439 | 73% |
| 待っている | 156 | 25% |
| ブロックされました | 7 | 1% |
439 RUNNABLE しかし、それらはどれも前進しておらず、彼らが目覚めてキャリアスレッドを待っていることを示しています。
その7つをもっと見てください BLOCKEDすべて同じ場所に詰まっています:
java.util.concurrent.ConcurrentHashMap.compute
← Caffeine BoundedLocalCache.computeIfAbsent
← LocalLoadingCache.get
← UserService.get(UserService.java:229)
← ... 业务批处理逻辑 ...
← VirtualThread.run
ConcurrentHashMap.compute 内側は synchronized。これら 7 つのスレッドは、他の人の手にあるモニターを待っています。モニターを握っているのは誰ですか?
スレッド スタックを見ると、ホルダーも仮想スレッドであることがわかります。 compute ロードロジックにログインします。待機しているのはログロックです。それは入っています synchronized 内部で待機しているロックがあるため、キャリア スレッドは固定されており、モニターを待機している 7 つのスレッドにも同じことが当てはまります。各キャリア スレッドは 1 つを占有し、移動できません。
最後に、仮想スレッドのデフォルト スケジューラを直接読み取ります。 VirtualThread.DEFAULT_SCHEDULER 状態：
ForkJoinPool[Running, parallelism = 8, size = 30, active = 8, running = 0, ...]
active = 8、running = 0。 8 つのキャリア スレッドがすべて占有されており、実際にコードを実行しているスレッドはありません。
それらをまとめてください
フローチャート TD A[批量任务：一下子产生几百个虚拟线程] –> B[大量虚拟线程打日志，争抢 AsyncAppender 队列锁]
A –> C[虚拟线程进入缓存加载的 synchronized]
C –> D[持有监视器的线程在里面打日志，等日志锁]
D –> E[它被 pin 在载体线程上；等监视器的线程也被 pin 住]
E –> F[8 条载体线程被占满，active=8 running=0]
B –> G[日志锁释放，AQS unpark 队头的虚拟线程]
G –> H[变成 RUNNABLE，但要等载体线程才能执行]
F –> H H –> I[没有载体线程，队头拿不到锁，锁空着，队列越排越长]
私 –> J[平台线程、Dubbo 查询线程也要打日志，全排进这把锁]
J –> K[日志冻结，接口超时，持续 13 小时]
これは 2 つのレベルにまたがるデッドロックです。
- アプリケーション層: モニターを保持しているスレッドは、終了する前にまずログ ロックを取得する必要があります。
synchronized - スケジューリング層: ログ ロック キューの先頭のスレッドは、ロックを取得する前にキャリア スレッドを持っている必要があり、キャリア スレッドは上のスレッドによって占有されています。
どのレイヤー単独でも問題はないため、jstack はデッドロックを検出できず、JVM 自体はデッドロックを報告しません。
この問題はAIと私が一緒に調査しました。
問題を検討する際に、ヒントを見つけたり、仮説を検証したりするのは難しいと思います。いつでもいくつかのことを思いつくことができますが、それぞれの山をスキャンし、ステータスを確認し、数値を比較するのに時間がかかるとします。 AI により検証ステップが非常に短縮され、コマンドによって数分で結果が得られます。
しかし、証拠が不十分な場合、AIは筋の通った話をでっち上げてしまい、脱線してしまうことがよくあります。今回はいくつかの説明があり、それらはすべて合理的に聞こえましたが、実際には検証されていませんでした。
そこで私がやることは主に2つです。結論が出たら「なぜ？」と尋ねます。方向性がないときは、自分の知識を使って方向性を与えます。これが、キャリアのスレッドがいっぱいであるという仮定の由来です。
指示を出して確認に行きます。証拠のない結論はカウントされません。
