Deadlock when using Virtual Threads
source link: https://jira.qos.ch/browse/LOGBACK-1711
Go to the source link to view the article. You can view the picture content, updated content and better typesetting reading experience. If the link is broken, please click the button below to view the snapshot at that time.
Deadlock when using Virtual Threads
Details
-
Type: Bug
-
Status: Open
-
Priority: Blocker
-
Resolution: Unresolved
-
Affects Version/s: 1.4.5
-
Fix Version/s: None
-
Component/s: logback-core
-
Labels:
-
Environment:
Microsoft Windows [Version 10.0.19045.2311]
openjdk 19.0.1 2022-10-18 OpenJDK Runtime Environment Temurin-19.0.1+10 (build 19.0.1+10) OpenJDK 64-Bit Server VM Temurin-19.0.1+10 (build 19.0.1+10, mixed mode, sharing)
Description
Repro steps:
- Unpack testcase.zip
- Run the Testcase class
- Application should deadlock at around "Progress: 340000" (within 10 seconds of startup for me)
This issue is 100% reproducible and only occurs when using JDK 19 virtual threads.
The bug seems to be triggered by RollingFileAppender.rollover().
Please note that using I/O inside synchronized blocks pins a carrier threads and this substantially reduces the performance of virtual threads. Please consider replacing such constructs with ReentrantLock or StampedLock as you have done elsewhere.
The deadlock might have something to do with all carrier threads waiting to acquire a synchronized block, while the thread holding the lock is blocked waiting for an I/O response. I'm not sure why the latter never comes back though...
- Options
Attachments
Activity
added a comment - 2 days ago - edited
Gili Hi Gili,
Thank you for this detailed report accompanied with a test case reproducing the problem. Which OS have you tested this on?
Also, is it correct to say that the semaphore is used to limit the number of concurrent threads to 5000?
added a comment - Yesterday - edited
Hi Ceki,
I've updated the Environment section of the bug report. I'm running under Windows 10.
Yes, the semaphore is used to limit the number of concurrent threads.
If you want to reproduce the bug even faster, you can make the following changes:
- Change maxFileSize to 1MB and totalSizeCap to 10MB in logback.xml
- Decrease the number of semaphore permits to 50
When I run this, I get a deadlock after a single line of output.
added a comment - Yesterday - edited
Thank you for the updates.
I have tried varying several parameters. In particular, it seems that when virtual threads are replaced with regular threads, then the test hums along for a long time without problems.
I also noticed that in case of a hang up with virtual threads, the thread dump provided by IDEA IntelliJ is near useless. The information provided by jstack does not seem much better.
From what I gathered thus far, the virtual threads get blocked when invoking a logger and never release the semaphore. This in turn causes the main thread to be blocked. Although the reason for the virtual threads getting blocked remains mysterious.
added a comment - Yesterday
Run with -Djdk.tracePinnedThreads=full to see if it reveals anything, it might be that logback is using a mix of monitors and j.u.c locks and this leads to this issue.
added a comment - Yesterday
Ceki,
I've never tried -Djdk.tracePinnedThreads=full as Alan mentioned but here is what worked for me:
- Run the test with "-Djdk.trackAllThreads=true"
- Once it hangs, run "jcmd <pid> Thread.dump_to_file <filename>" from a terminal
This will give you a thread dump containing virtual threads (unlike the old mechanism which only shows carrier threads).
People
Assignee:
Logback dev list Reporter:
Gili
Dates
Recommend
About Joyk
Aggregate valuable and interesting links.
Joyk means Joy of geeK