4

Deadlock when using Virtual Threads

 1 year ago
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: viewavatar?size=xsmall&avatarId=11103&avatarType=issuetype Bug
  • Status: Open
  • Priority: blocker.svg 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:

  1. Unpack testcase.zip
  2. Run the Testcase class
  3. 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 Logback dev list Reporter:

cowwoc Gili

Votes: 0 Vote for this issue Watchers: 3 Start watching this issue

Dates

Created: 2 days ago Updated: Yesterday

About Joyk


Aggregate valuable and interesting links.
Joyk means Joy of geeK