Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

thread blocked in virtual thread envrionment with 1.4.14 version #767

Open
walkertest opened this issue Jan 12, 2024 · 7 comments
Open

thread blocked in virtual thread envrionment with 1.4.14 version #767

walkertest opened this issue Jan 12, 2024 · 7 comments

Comments

@walkertest
Copy link

walkertest commented Jan 12, 2024

Env

  • Logback version :1.4.14
  • Springboot version: 3.2.1
  • My server framework with a reactor model which is like the opensource framework-tars :https://github.com/TarsCloud/TarsJava . I support the virtual thread model .
  • The stress request qps: 30_000/s
  • javaVersion:openjdk version "21" 2023-09-19/OpenJDK Runtime Environment (build 21+35-2513)/OpenJDK 64-Bit Server VM (build 21+35-2513, mixed mode, sharing)

Problem

  • My server thread was blocked by logger.error method. And then my program cannot handle new request.

the request and response

The thread stack

  • You can see my reactor thread is waiting for the logger.error method.

  • The full thread stack is in the added file.
    stack1.txt

  • the jcmd thread dump info(jcmd Thread.dump_to_file ):
    thread_jcmdaa.txt
    thread_jcmdab.txt

"ts-reactor-0" #47 [693] prio=5 os_prio=0 cpu=195123.31ms elapsed=69926.73s tid=0x00007fbc7a0daf10 nid=693 waiting on condition  [0x00007fbc4cebf000]
   java.lang.Thread.State: WAITING (parking)
	at jdk.internal.misc.Unsafe.park(java.base@21/Native Method)
	- parking to wait for  <0x0000000759b899e8> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
	at java.util.concurrent.locks.LockSupport.park(java.base@21/LockSupport.java:371)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionNode.block(java.base@21/AbstractQueuedSynchronizer.java:519)
	at java.util.concurrent.ForkJoinPool.unmanagedBlock(java.base@21/ForkJoinPool.java:3780)
	at java.util.concurrent.ForkJoinPool.managedBlock(java.base@21/ForkJoinPool.java:3725)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(java.base@21/AbstractQueuedSynchronizer.java:1707)
	at java.util.concurrent.ArrayBlockingQueue.put(java.base@21/ArrayBlockingQueue.java:370)
	at ch.qos.logback.core.AsyncAppenderBase.putUninterruptibly(AsyncAppenderBase.java:186)
	at ch.qos.logback.core.AsyncAppenderBase.put(AsyncAppenderBase.java:177)
	at ch.qos.logback.core.AsyncAppenderBase.append(AsyncAppenderBase.java:166)
	at ch.qos.logback.core.UnsynchronizedAppenderBase.doAppend(UnsynchronizedAppenderBase.java:85)
	at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:51)
	at ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:272)
	at ch.qos.logback.classic.Logger.callAppenders(Logger.java:259)
	at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:426)
	at ch.qos.logback.classic.Logger.filterAndLog_0_Or3Plus(Logger.java:386)
	at ch.qos.logback.classic.Logger.error(Logger.java:539)
	at com.huya.taf.net.core.nio.TCPSession.handleVtServer(TCPSession.java:218)
	at com.huya.taf.net.core.nio.TCPSession.readRequest(TCPSession.java:177)
	at com.huya.taf.net.core.nio.TCPSession.read(TCPSession.java:140)
	at com.huya.taf.net.core.nio.TCPAcceptor.handleReadEvent(TCPAcceptor.java:111)
	at com.huya.taf.net.core.nio.Reactor.dispatchEvent(Reactor.java:197)
	at com.huya.taf.net.core.nio.Reactor.run(Reactor.java:114)

"ts-reactor-1" #48 [694] prio=5 os_prio=0 cpu=223469.95ms elapsed=69926.73s tid=0x00007fbc7a0eda90 nid=694 waiting on condition  [0x00007fbc4ce7e000]
   java.lang.Thread.State: WAITING (parking)
	at jdk.internal.misc.Unsafe.park(java.base@21/Native Method)
	- parking to wait for  <0x0000000759b899e8> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
	at java.util.concurrent.locks.LockSupport.park(java.base@21/LockSupport.java:371)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionNode.block(java.base@21/AbstractQueuedSynchronizer.java:519)
	at java.util.concurrent.ForkJoinPool.unmanagedBlock(java.base@21/ForkJoinPool.java:3780)
	at java.util.concurrent.ForkJoinPool.managedBlock(java.base@21/ForkJoinPool.java:3725)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(java.base@21/AbstractQueuedSynchronizer.java:1707)
	at java.util.concurrent.ArrayBlockingQueue.put(java.base@21/ArrayBlockingQueue.java:370)
	at ch.qos.logback.core.AsyncAppenderBase.putUninterruptibly(AsyncAppenderBase.java:186)
	at ch.qos.logback.core.AsyncAppenderBase.put(AsyncAppenderBase.java:177)
	at ch.qos.logback.core.AsyncAppenderBase.append(AsyncAppenderBase.java:166)
	at ch.qos.logback.core.UnsynchronizedAppenderBase.doAppend(UnsynchronizedAppenderBase.java:85)
	at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:51)
	at ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:272)
	at ch.qos.logback.classic.Logger.callAppenders(Logger.java:259)
	at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:426)
	at ch.qos.logback.classic.Logger.filterAndLog_0_Or3Plus(Logger.java:386)
	at ch.qos.logback.classic.Logger.error(Logger.java:539)
	at com.huya.taf.net.core.nio.Reactor.disConnectWithException(Reactor.java:144)
	at com.huya.taf.net.core.nio.Reactor.run(Reactor.java:117)

"ts-reactor-2" #49 [695] prio=5 os_prio=0 cpu=196075.69ms elapsed=69926.73s tid=0x00007fbc7a0eec00 nid=695 waiting on condition  [0x00007fbc4ce3d000]
   java.lang.Thread.State: WAITING (parking)
	at jdk.internal.misc.Unsafe.park(java.base@21/Native Method)
	- parking to wait for  <0x0000000759b895b8> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)
	at java.util.concurrent.locks.LockSupport.park(java.base@21/LockSupport.java:221)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(java.base@21/AbstractQueuedSynchronizer.java:754)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(java.base@21/AbstractQueuedSynchronizer.java:990)
	at java.util.concurrent.locks.ReentrantLock$Sync.lock(java.base@21/ReentrantLock.java:153)
	at java.util.concurrent.locks.ReentrantLock.lock(java.base@21/ReentrantLock.java:322)
	at java.util.concurrent.ArrayBlockingQueue.remainingCapacity(java.base@21/ArrayBlockingQueue.java:485)
	at ch.qos.logback.core.AsyncAppenderBase.isQueueBelowDiscardingThreshold(AsyncAppenderBase.java:170)
	at ch.qos.logback.core.AsyncAppenderBase.append(AsyncAppenderBase.java:162)
	at ch.qos.logback.core.UnsynchronizedAppenderBase.doAppend(UnsynchronizedAppenderBase.java:85)
	at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:51)
	at ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:272)
	at ch.qos.logback.classic.Logger.callAppenders(Logger.java:259)
	at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:426)
	at ch.qos.logback.classic.Logger.filterAndLog_2(Logger.java:419)
	at ch.qos.logback.classic.Logger.info(Logger.java:592)
	at com.huya.taf.net.core.nio.TCPSession.handleVtServer(TCPSession.java:208)
	at com.huya.taf.net.core.nio.TCPSession.readRequest(TCPSession.java:177)
	at com.huya.taf.net.core.nio.TCPSession.read(TCPSession.java:140)
	at com.huya.taf.net.core.nio.TCPAcceptor.handleReadEvent(TCPAcceptor.java:111)
	at com.huya.taf.net.core.nio.Reactor.dispatchEvent(Reactor.java:197)
	at com.huya.taf.net.core.nio.Reactor.run(Reactor.java:114)

"ts-reactor-3" #50 [696] prio=5 os_prio=0 cpu=194924.27ms elapsed=69926.73s tid=0x00007fbc7a0f0020 nid=696 waiting on condition  [0x00007fbc4cdfc000]
   java.lang.Thread.State: WAITING (parking)
	at jdk.internal.misc.Unsafe.park(java.base@21/Native Method)
	- parking to wait for  <0x0000000759b899e8> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
	at java.util.concurrent.locks.LockSupport.park(java.base@21/LockSupport.java:371)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionNode.block(java.base@21/AbstractQueuedSynchronizer.java:519)
	at java.util.concurrent.ForkJoinPool.unmanagedBlock(java.base@21/ForkJoinPool.java:3780)
	at java.util.concurrent.ForkJoinPool.managedBlock(java.base@21/ForkJoinPool.java:3725)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(java.base@21/AbstractQueuedSynchronizer.java:1707)
	at java.util.concurrent.ArrayBlockingQueue.put(java.base@21/ArrayBlockingQueue.java:370)
	at ch.qos.logback.core.AsyncAppenderBase.putUninterruptibly(AsyncAppenderBase.java:186)
	at ch.qos.logback.core.AsyncAppenderBase.put(AsyncAppenderBase.java:177)
	at ch.qos.logback.core.AsyncAppenderBase.append(AsyncAppenderBase.java:166)
	at ch.qos.logback.core.UnsynchronizedAppenderBase.doAppend(UnsynchronizedAppenderBase.java:85)
	at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:51)
	at ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:272)
	at ch.qos.logback.classic.Logger.callAppenders(Logger.java:259)
	at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:426)
	at ch.qos.logback.classic.Logger.filterAndLog_0_Or3Plus(Logger.java:386)
	at ch.qos.logback.classic.Logger.error(Logger.java:539)
	at com.huya.taf.net.core.nio.TCPSession.handleVtServer(TCPSession.java:218)
	at com.huya.taf.net.core.nio.TCPSession.readRequest(TCPSession.java:177)
	at com.huya.taf.net.core.nio.TCPSession.read(TCPSession.java:140)
	at com.huya.taf.net.core.nio.TCPAcceptor.handleReadEvent(TCPAcceptor.java:111)
	at com.huya.taf.net.core.nio.Reactor.dispatchEvent(Reactor.java:197)
	at com.huya.taf.net.core.nio.Reactor.run(Reactor.java:114)

"ts-reactor-4" #51 [697] prio=5 os_prio=0 cpu=194829.49ms elapsed=69926.73s tid=0x00007fbc7a0f15b0 nid=697 waiting on condition  [0x00007fbc4cdbb000]
   java.lang.Thread.State: WAITING (parking)
	at jdk.internal.misc.Unsafe.park(java.base@21/Native Method)
	- parking to wait for  <0x0000000759b899e8> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
	at java.util.concurrent.locks.LockSupport.park(java.base@21/LockSupport.java:371)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionNode.block(java.base@21/AbstractQueuedSynchronizer.java:519)
	at java.util.concurrent.ForkJoinPool.unmanagedBlock(java.base@21/ForkJoinPool.java:3780)
	at java.util.concurrent.ForkJoinPool.managedBlock(java.base@21/ForkJoinPool.java:3725)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(java.base@21/AbstractQueuedSynchronizer.java:1707)
	at java.util.concurrent.ArrayBlockingQueue.put(java.base@21/ArrayBlockingQueue.java:370)
	at ch.qos.logback.core.AsyncAppenderBase.putUninterruptibly(AsyncAppenderBase.java:186)
	at ch.qos.logback.core.AsyncAppenderBase.put(AsyncAppenderBase.java:177)
	at ch.qos.logback.core.AsyncAppenderBase.append(AsyncAppenderBase.java:166)
	at ch.qos.logback.core.UnsynchronizedAppenderBase.doAppend(UnsynchronizedAppenderBase.java:85)
	at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:51)
	at ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:272)
	at ch.qos.logback.classic.Logger.callAppenders(Logger.java:259)
	at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:426)
	at ch.qos.logback.classic.Logger.filterAndLog_2(Logger.java:419)
	at ch.qos.logback.classic.Logger.info(Logger.java:592)
	at com.huya.taf.net.core.nio.TCPSession.handleVtServer(TCPSession.java:208)
	at com.huya.taf.net.core.nio.TCPSession.readRequest(TCPSession.java:177)
	at com.huya.taf.net.core.nio.TCPSession.read(TCPSession.java:140)
	at com.huya.taf.net.core.nio.TCPAcceptor.handleReadEvent(TCPAcceptor.java:111)
	at com.huya.taf.net.core.nio.Reactor.dispatchEvent(Reactor.java:197)
	at com.huya.taf.net.core.nio.Reactor.run(Reactor.java:114)
@walkertest
Copy link
Author

walkertest commented Jan 14, 2024

jcmd Thread.dump_to_file info:
The dump file is bigger than 26M(the github issue limit), so i split the file to two files.

thread_jcmdaa.txt
thread_jcmdab.txt

@ArtemiyVorobev
Copy link

ArtemiyVorobev commented Feb 15, 2024

On your project we have the same problem. Waiting for fix

@ArtemiyVorobev
Copy link

@walkertest Have you found a work around ?

@ceki
Copy link
Member

ceki commented Feb 15, 2024

@walkertest Can you please provide the logback configuration file?

@walkertest
Copy link
Author

@walkertest Have you found a work around ?

Not yet. Do you have solve this problem?
My co-worker had meet this problem again

@walkertest
Copy link
Author

@walkertest Can you please provide the logback configuration file?

<!-- 项目名称 -->
<springProperty scope="context" name="springProjectName" source="spring.project.name" defaultValue="huyapassport" />
<!-- 模块名称 -->
<springProperty scope="context" name="springAppName" source="spring.application.name"  defaultValue="virtualThread"/>

<property name="LOG_PATTERN"
          value="%d{yyyy-MM-dd HH:mm:ss.SSS} %-5level %marker ${springAppName:-} [%thread] [%X{traceId:-}] %logger{1} --- %msg%n"/>

<property name="LOG_DIR" value="/data/log/huyapassport/"/>


<!--控制台输出 -->
<appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
    <encoder>
        <pattern>${LOG_PATTERN}</pattern>
    </encoder>
</appender>

<appender name="DETAILS" class="ch.qos.logback.core.rolling.RollingFileAppender">
    <file>${LOG_DIR}/udb_server_details/${springAppName}.log</file>
    <rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
        <fileNamePattern>${LOG_DIR}/udb_server_details/${springAppName}.%d{yyyy-MM-dd,Asia/Hong_Kong}.%i.log</fileNamePattern>
        <maxFileSize>800MB</maxFileSize>
        <maxHistory>60</maxHistory>
        <totalSizeCap>20GB</totalSizeCap>
    </rollingPolicy>
    <encoder>
        <pattern>${LOG_PATTERN}</pattern>
    </encoder>
</appender>

<appender name="TAFLOG" class="ch.qos.logback.core.rolling.RollingFileAppender">
    <file>${LOG_DIR}/taflog/${springAppName}.log</file>
    <rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
        <fileNamePattern>${LOG_DIR}/taflog/${springAppName}.%d{yyyy-MM-dd,Asia/Hong_Kong}.%i.log</fileNamePattern>
        <maxFileSize>800MB</maxFileSize>
        <maxHistory>60</maxHistory>
        <totalSizeCap>20GB</totalSizeCap>
    </rollingPolicy>
    <encoder>
        <pattern>${LOG_PATTERN}</pattern>
    </encoder>
</appender>
<appender name="taflogAppender" class="ch.qos.logback.classic.AsyncAppender">
    <appender-ref ref="TAFLOG" />
</appender>


<appender name="detailsAppender" class="ch.qos.logback.classic.AsyncAppender">
    <appender-ref ref="DETAILS" />
</appender>

<root level="INFO">
    <springProfile name="dev">
        <!--开发开启控制台输出 -->
        <appender-ref ref="STDOUT" />
        <appender-ref ref="detailsAppender" />
    </springProfile>

    <springProfile name="test,pre,prod">
        <appender-ref ref="detailsAppender" />
    </springProfile>

</root>

<logger name="com.huya.taf" additivity="false" level="DEBUG">
    <appender-ref ref="taflogAppender" />
</logger>

@apflieger
Copy link

We have the same issue, it crashed our prod two times, then we rolled back the usage of virtual threads.
Here's our config.

<?xml version="1.0" encoding="UTF-8" ?>
<configuration>
  <property name="TIMEZONE" value="Europe/Paris" />
  <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
    <encoder>
      <!-- coloring the level without the brackets doesn't work -->
      <pattern>%date{ISO8601, ${TIMEZONE}} %highlight(%-7([%level])) %X{executionContext:-(no execution context)} - %logger - %message%n%xException</pattern>
    </encoder>
  </appender>
  <appender name="ASYNCSTDOUT" class="ch.qos.logback.classic.AsyncAppender">
    <appender-ref ref="STDOUT" />
  </appender>
  <appender name="EMAIL" class="ch.qos.logback.classic.net.SMTPAppender">
    <smtpHost>${email.smtp.host}</smtpHost>
    <smtpPort>${email.smtp.port}</smtpPort>
    <SSL>${email.smtp.ssl}</SSL>
    <username>${email.smtp.user}</username>
    <password>${email.smtp.password}</password>
    <from>Logback ${app.env} &lt;${email.logback_recipient}&gt;</from><!-- So we can respond to it -->
    <to>${email.logback_recipient}</to>
    <subject>%logger{0} - %message</subject>
    <layout class="ch.qos.logback.classic.PatternLayout">
      <pattern>%date{ISO8601, ${TIMEZONE}} [%level] %X{executionContext:-(no execution context)} - %logger - %message%n%xException</pattern>
    </layout>
    <discriminator class="ch.qos.logback.classic.sift.MDCBasedDiscriminator">
      <key>executionContext</key>
      <defaultValue>default</defaultValue>
    </discriminator>
  </appender>
  <root level="WARN"> <!-- External libraries don't log that much interesting stuff -->
    <appender-ref ref="ASYNCSTDOUT" />
    <appender-ref ref="EMAIL" />
  </root>
  <logger name="com.zaxxer.hikari.pool.HikariPool" level="ERROR" /> <!-- Ignore clock leap warnings. This happens a lot when dev laptops are put to sleep. -->
  <logger name="org.apache.http.client.protocol.ResponseProcessCookies" level="ERROR" /> <!-- We get a lot of invalid cookies warnings from bots like this: Invalid cookie header: "Set-Cookie: AWSALBTGCORS=0hymVtXBvpvwanwaGglsFN0gnZp0XOtyI0Kyf5Muv57QcG09yKvyc7xBJpJ4SvWNwa++q7r4zxpSnYSPD0wTMTfoyeJifDU2V1dZsi19K73P+kmXKlHzGFNAiLXQcg4+vcx9K0F9kbU6QAfXYe2I3VB7kxd5TLfdeYAJOdXn3Bkv; Expires=Wed, 13 Apr 2022 11:03:00 GMT; Path=/; SameSite=None; Secure". Invalid 'expires' attribute: Wed, 13 Apr 2022 11:03:00 GMT -->
  <logger name="com.meetinclass" level="DEBUG" />
  <logger name="Javascript" level="DEBUG" />
  <!--
  <logger name="io.ebean" level="DEBUG"/>
  <logger name="io.ebeaninternal" level="DEBUG"/>
  <logger name="io.ebean.SQL" level="DEBUG"/>
  <logger name="io.ebean.SUM" level="DEBUG"/>
  -->
</configuration>

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

4 participants