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.

Sign up for GitHub

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

Jump to bottom

Thread blocked on JBossLoggingAccessLogReceiver #44779

Closed
dfa1 opened this issue Nov 27, 2024 · 8 comments
Closed

Thread blocked on JBossLoggingAccessLogReceiver #44779

dfa1 opened this issue Nov 27, 2024 · 8 comments
Labels
area/logging area/mutiny area/vertx kind/bug Something isn't working

Comments

@dfa1
Copy link
Contributor

dfa1 commented Nov 27, 2024

Describe the bug

From time to time, we have this exception in quarkus 3.15.1
with the following message:

Thread[vert.x-eventloop-thread-2,5,main] has been blocked for 3893 ms, time limit is 2000 ms

and stacktrace:

io.vertx.core.VertxException: Thread blocked
	at [email protected]/java.math.BigDecimal.valueOf(BigDecimal.java:1315)
	at [email protected]/java.math.BigDecimal.valueOf(BigDecimal.java:1291)
	at [email protected]/java.math.BigDecimal.add(BigDecimal.java:4994)
	at [email protected]/java.math.BigDecimal.add(BigDecimal.java:5001)
	at [email protected]/java.math.BigDecimal.subtract(BigDecimal.java:1528)
	at [email protected]/java.time.format.DateTimeFormatterBuilder$FractionPrinterParser.convertToFraction(DateTimeFormatterBuilder.java:3295)
	at [email protected]/java.time.format.DateTimeFormatterBuilder$FractionPrinterParser.format(DateTimeFormatterBuilder.java:3212)
	at [email protected]/java.time.format.DateTimeFormatterBuilder$CompositePrinterParser.format(DateTimeFormatterBuilder.java:2402)
	at [email protected]/java.time.format.DateTimeFormatter.formatTo(DateTimeFormatter.java:1849)
	at app//org.jboss.logmanager.formatters.Formatters$7.renderRaw(Formatters.java:488)
	at app//org.jboss.logmanager.formatters.Formatters$JustifyingFormatStep.render(Formatters.java:227)
	at app//org.jboss.logmanager.formatters.MultistepFormatter.format(MultistepFormatter.java:90)
	at app//org.jboss.logmanager.ExtFormatter$Delegating.format(ExtFormatter.java:196)
	at app//org.jboss.logmanager.ExtFormatter.format(ExtFormatter.java:58)
	at app//org.jboss.logmanager.handlers.WriterHandler.doPublish(WriterHandler.java:52)
	at app//org.jboss.logmanager.ExtHandler.publish(ExtHandler.java:88)
	at app//org.jboss.logmanager.ExtHandler.publishToNestedHandlers(ExtHandler.java:125)
	at app//io.quarkus.bootstrap.logging.QuarkusDelayedHandler.doPublish(QuarkusDelayedHandler.java:81)
	at app//org.jboss.logmanager.ExtHandler.publish(ExtHandler.java:88)
	at app//org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:438)
	at app//org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:480)
	at app//org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:480)
	at app//org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:480)
	at app//org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:480)
	at app//org.jboss.logmanager.Logger.logRaw(Logger.java:1089)
	at app//org.jboss.logmanager.Logger.log(Logger.java:1052)
	at app//org.jboss.logmanager.Logger.log(Logger.java:1064)
	at app//org.jboss.logging.JBossLogManagerLogger.doLog(JBossLogManagerLogger.java:43)
	at app//org.jboss.logging.Logger.info(Logger.java:957)
	at io.quarkus.vertx.http.runtime.filters.accesslog.JBossLoggingAccessLogReceiver.logMessage(JBossLoggingAccessLogReceiver.java:44)
	at io.quarkus.vertx.http.runtime.filters.accesslog.AccessLogHandler$1.handle(AccessLogHandler.java:158)
	at io.quarkus.vertx.http.runtime.filters.accesslog.AccessLogHandler$1.handle(AccessLogHandler.java:155)
	at io.quarkus.vertx.http.runtime.filters.QuarkusRequestWrapper.done(QuarkusRequestWrapper.java:73)
	at io.quarkus.vertx.http.runtime.filters.QuarkusRequestWrapper$ResponseWrapper$3.handle(QuarkusRequestWrapper.java:143)
	at io.quarkus.vertx.http.runtime.filters.QuarkusRequestWrapper$ResponseWrapper$3.handle(QuarkusRequestWrapper.java:140)
	at io.vertx.core.http.impl.Http1xServerResponse.end(Http1xServerResponse.java:443)
	at io.vertx.core.http.impl.Http1xServerResponse.end(Http1xServerResponse.java:411)
	at io.quarkus.vertx.http.runtime.filters.AbstractResponseWrapper.end(AbstractResponseWrapper.java:234)
	at io.quarkus.smallrye.health.runtime.SmallRyeHealthHandlerBase.lambda$doHandle$0(SmallRyeHealthHandlerBase.java:68)
	at io.quarkus.smallrye.health.runtime.SmallRyeHealthHandlerBase$$Lambda$728/0x00007faa7c5c4f10.accept(Unknown Source)
	at io.smallrye.context.impl.wrappers.SlowContextualConsumer.accept(SlowContextualConsumer.java:21)
	at io.smallrye.mutiny.helpers.UniCallbackSubscriber.onItem(UniCallbackSubscriber.java:73)
	at io.smallrye.mutiny.operators.uni.UniEmitOn$UniEmitOnProcessor.lambda$onItem$0(UniEmitOn.java:34)
	at io.smallrye.mutiny.operators.uni.UniEmitOn$UniEmitOnProcessor$$Lambda$738/0x00007faa7c5cf490.run(Unknown Source)
	at io.smallrye.mutiny.vertx.MutinyHelper.lambda$executor$2(MutinyHelper.java:32)
	at io.smallrye.mutiny.vertx.MutinyHelper$$Lambda$739/0x00007faa7c5cf6c0.handle(Unknown Source)
	at io.vertx.core.impl.ContextInternal.dispatch(ContextInternal.java:270)
	at io.vertx.core.impl.ContextInternal.dispatch(ContextInternal.java:252)
	at io.vertx.core.impl.ContextInternal.lambda$runOnContext$0(ContextInternal.java:50)
	at io.vertx.core.impl.ContextInternal$$Lambda$390/0x00007faa7c413918.run(Unknown Source)
	at io.netty.util.concurrent.AbstractEventExecutor.runTask(AbstractEventExecutor.java:173)
	at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:166)
	at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:469)
	at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:569)
	at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:994)
	at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
	at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
	at [email protected]/java.lang.Thread.run(Thread.java:840)

I don't see anything pointing to our code in the stacktrace. I opened this issue to see if someone is already aware of the issue or root cause.

Expected behavior

No thread blocked

Actual behavior

The above stacktrace from time to time, especially under heavy load.

How to Reproduce?

It happens from time to time, especially during heavy load.

Output of uname -a or ver

Linux api-blue-5f89f4b44f-pdtf2 5.14.0-284.88.1.el9_2.x86_64 #1 SMP PREEMPT_DYNAMIC Fri Oct 4 11:09:23 EDT 2024 x86_64 x86_64 x86_64 GNU/Linux

Output of java -version

OpenJDK 17.0.13

Quarkus version or git rev

3.15.1

Build tool (ie. output of mvnw --version or gradlew --version)

maven 3.3.2

Additional information

No response
@dfa1 dfa1 added the kind/bug Something isn't working label Nov 27, 2024
@dfa1
Copy link
Contributor Author

dfa1 commented Nov 27, 2024 •
edited
Loading

There is also this stacktrace from time to time:

Thread Thread[vert.x-eventloop-thread-4,5,main] has been blocked for 13231 ms, time limit is 2000 ms

  io.vertx.core.VertxException: Thread blocked
	at [email protected]/sun.nio.ch.EPoll.wait(Native Method)
	at [email protected]/sun.nio.ch.EPollSelectorImpl.doSelect(EPollSelectorImpl.java:118)
	at [email protected]/sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:129)
	at [email protected]/sun.nio.ch.SelectorImpl.select(SelectorImpl.java:141)
	at io.netty.channel.nio.SelectedSelectionKeySetSelector.select(SelectedSelectionKeySetSelector.java:62)
	at io.netty.channel.nio.NioEventLoop.select(NioEventLoop.java:883)
	at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:526)
	at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:994)
	at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
	at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
	at [email protected]/java.lang.Thread.run(Thread.java:840)

@quarkus-bot quarkus-bot
Copy link

quarkus-bot bot commented Nov 27, 2024

/cc @dmlloyd (logging)

@dmlloyd
Copy link
Member

dmlloyd commented Nov 27, 2024 •
edited
Loading

While logging does appear in this stack trace, it's not very likely that the thread itself is blocked in logging; more likely, it is logging as a part of some kind of operation that is blocking and should not be. Also the latter one seems like a real problem. Maybe the Vert.x context is getting messed up somehow?

Is there any chance of providing a reproducer?

@dfa1
Copy link
Contributor Author

dfa1 commented Nov 27, 2024

@dmlloyd it would be very hard to extract a reproduce but I will try.

In the meantime: our code is not using Vert.x directly.
In your experience, what could be the root cause? I see it happens when the JVM is about to die (too much GC pressure).

@dmlloyd
Copy link
Member

dmlloyd commented Nov 27, 2024

Ah, well it's possible then that the thread is blocking in GC and thus exceeding the max time threshold. The warning doesn't mean "blocked" per se, rather that too much time elapsed since an asynchronous task was submitted without it returning.

@geoand
Copy link
Contributor

geoand commented Nov 28, 2024

My guess is that the machine is approaching its capacity under the given load so pretty much anything that is on the event loop could start causing these messages

@dfa1
Copy link
Contributor Author

dfa1 commented Nov 28, 2024

ok, I'm going to close this one then!
Thanks for the feedback!

@dfa1 dfa1 closed this as completed Nov 28, 2024
@geoand
Copy link
Contributor

geoand commented Nov 28, 2024

👌

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
area/logging area/mutiny area/vertx kind/bug Something isn't working
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@dmlloyd @geoand @dfa1