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

Vertx Thread blocked even with @Blocking on gRPC service #45830

Open
ncabanis opened this issue Jan 23, 2025 · 3 comments
Open

Vertx Thread blocked even with @Blocking on gRPC service #45830

ncabanis opened this issue Jan 23, 2025 · 3 comments
Labels
area/grpc gRPC area/vertx kind/bug Something isn't working

Comments

@ncabanis
Copy link

Describe the bug

The Vertx thread is blocked, even though the @Blocking annotation is used to indicate work should be done on a dedicated worker thread.

@GrpcService
class TraceExportEndpoint() : TraceServiceGrpc.TraceServiceImplBase()
{
    @Blocking
    override fun export(
        request: ExportTraceServiceRequest,
        responseObserver: StreamObserver<ExportTraceServiceResponse>
    ) {
       ...
   }

Expected behavior

With the @Blocking annotation, my expectation would be that all work is done in worker threads.
The parsing of the gRPC message can be CPU intensive, especially for larger messages. If the system is under heavy load, then the Vertx thread should not be blocked.

Actual behavior

2025-01-23 14:47:58,939 WARN  [ io.ve.co.im.BlockedThreadChecker] (vertx-blocked-thread-checker) Thread Thread[vert.x-eventloop-thread-1,5,main] has been blocked for 3231 ms, time limit is 2000 ms: io.vertx.core.VertxException: Thread blocked
	at java.base/java.lang.String.<init>(String.java:522)
	at com.google.protobuf.Utf8$UnsafeProcessor.decodeUtf8(Utf8.java:1347)
	at com.google.protobuf.Utf8.decodeUtf8(Utf8.java:318)
	at com.google.protobuf.CodedInputStream$StreamDecoder.readStringRequireUtf8(CodedInputStream.java:2313)
	at io.opentelemetry.proto.common.v1.AnyValue$Builder.mergeFrom(AnyValue.java:753)
	at io.opentelemetry.proto.common.v1.AnyValue$1.parsePartialFrom(AnyValue.java:1425)
	at io.opentelemetry.proto.common.v1.AnyValue$1.parsePartialFrom(AnyValue.java:1419)
	at com.google.protobuf.CodedInputStream$StreamDecoder.readMessage(CodedInputStream.java:2374)
	at io.opentelemetry.proto.common.v1.ArrayValue$Builder.mergeFrom(ArrayValue.java:427)
	at io.opentelemetry.proto.common.v1.ArrayValue$Builder.mergeFrom(ArrayValue.java:255)
	at com.google.protobuf.CodedInputStream$StreamDecoder.readMessage(CodedInputStream.java:2358)
	at io.opentelemetry.proto.common.v1.AnyValue$Builder.mergeFrom(AnyValue.java:782)
	at io.opentelemetry.proto.common.v1.AnyValue$Builder.mergeFrom(AnyValue.java:562)
	at com.google.protobuf.CodedInputStream$StreamDecoder.readMessage(CodedInputStream.java:2358)
	at io.opentelemetry.proto.common.v1.KeyValue$Builder.mergeFrom(KeyValue.java:440)
	at io.opentelemetry.proto.common.v1.KeyValue$1.parsePartialFrom(KeyValue.java:692)
	at io.opentelemetry.proto.common.v1.KeyValue$1.parsePartialFrom(KeyValue.java:686)
	at com.google.protobuf.CodedInputStream$StreamDecoder.readMessage(CodedInputStream.java:2374)
	at io.opentelemetry.proto.resource.v1.Resource$Builder.mergeFrom(Resource.java:470)
	at io.opentelemetry.proto.resource.v1.Resource$Builder.mergeFrom(Resource.java:291)
	at com.google.protobuf.CodedInputStream$StreamDecoder.readMessage(CodedInputStream.java:2358)
	at io.opentelemetry.proto.trace.v1.ResourceSpans$Builder.mergeFrom(ResourceSpans.java:585)
	at io.opentelemetry.proto.trace.v1.ResourceSpans$1.parsePartialFrom(ResourceSpans.java:1250)
	at io.opentelemetry.proto.trace.v1.ResourceSpans$1.parsePartialFrom(ResourceSpans.java:1244)
	at com.google.protobuf.CodedInputStream$StreamDecoder.readMessage(CodedInputStream.java:2374)
	at io.opentelemetry.proto.collector.trace.v1.ExportTraceServiceRequest$Builder.mergeFrom(ExportTraceServiceRequest.java:437)
	at io.opentelemetry.proto.collector.trace.v1.ExportTraceServiceRequest$1.parsePartialFrom(ExportTraceServiceRequest.java:880)
	at io.opentelemetry.proto.collector.trace.v1.ExportTraceServiceRequest$1.parsePartialFrom(ExportTraceServiceRequest.java:874)
	at com.google.protobuf.AbstractParser.parseFrom(AbstractParser.java:63)
	at com.google.protobuf.AbstractParser.parseFrom(AbstractParser.java:25)
	at io.grpc.protobuf.lite.ProtoLiteUtils$MessageMarshaller.parseFrom(ProtoLiteUtils.java:245)
	at io.grpc.protobuf.lite.ProtoLiteUtils$MessageMarshaller.parse(ProtoLiteUtils.java:237)
	at io.grpc.protobuf.lite.ProtoLiteUtils$MessageMarshaller.parse(ProtoLiteUtils.java:134)
	at io.grpc.MethodDescriptor.parseRequest(MethodDescriptor.java:307)
	at io.grpc.internal.ServerCallImpl$ServerStreamListenerImpl.messagesAvailableInternal(ServerCallImpl.java:334)
	at io.grpc.internal.ServerCallImpl$ServerStreamListenerImpl.messagesAvailable(ServerCallImpl.java:319)
	at io.grpc.internal.ServerImpl$JumpToApplicationThreadServerStreamListener$1MessagesAvailable.runInContext(ServerImpl.java:834)
	at io.grpc.internal.ContextRunnable.run(ContextRunnable.java:37)
	at io.grpc.internal.SerializingExecutor.run(SerializingExecutor.java:133)
	at io.vertx.grpc.VertxServer$ActualServer.lambda$null$0(VertxServer.java:97)
	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.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:566)
	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 java.base/java.lang.Thread.run(Thread.java:1583)

How to Reproduce?

I can try to create a reproducer, if this is accepted as bug.

Output of uname -a or ver

No response

Output of java -version

No response

Quarkus version or git rev

3.14.4

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

Gradle 8.9

Additional information

application.properties:

# reverted to use separate servers, due to
# https://github.com/quarkusio/quarkus/issues/43573
quarkus.grpc.server.use-separate-server=true
quarkus.grpc.server.port=4317
quarkus.grpc.server.max-inbound-message-size=500000000
quarkus.grpc.server.enable-reflection-service=true
@ncabanis ncabanis added the kind/bug Something isn't working label Jan 23, 2025
@quarkus-bot quarkus-bot
Copy link

quarkus-bot bot commented Jan 23, 2025

/cc @alesj (grpc), @cescoffier (grpc)

@ncabanis
Copy link
Author

Additional stack traces:

2025-01-23 15:16:11,235 WARN  [ io.ve.co.im.BlockedThreadChecker] (vertx-blocked-thread-checker) Thread Thread[vert.x-eventloop-thread-1,5,main] has been blocked for 3001 ms, time limit is 2000 ms: io.vertx.core.VertxException: Thread blocked
	at io.grpc.Context$CancellableContext.notifyAndClearListeners(Context.java:858)
	at io.grpc.Context$CancellableContext.cancel(Context.java:833)
	at io.grpc.internal.ServerCallImpl$ServerStreamListenerImpl.closedInternal(ServerCallImpl.java:384)
	at io.grpc.internal.ServerCallImpl$ServerStreamListenerImpl.closed(ServerCallImpl.java:364)
	at io.grpc.internal.ServerImpl$JumpToApplicationThreadServerStreamListener$1Closed.runInContext(ServerImpl.java:910)
	at io.grpc.internal.ContextRunnable.run(ContextRunnable.java:37)
	at io.grpc.internal.SerializingExecutor.run(SerializingExecutor.java:133)
	at io.vertx.grpc.VertxServer$ActualServer.lambda$null$0(VertxServer.java:97)
	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.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:566)
	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 java.base/java.lang.Thread.run(Thread.java:1583)

This stack trace on the other hand might be an indication that the underlying system might really be at the edge:

2025-01-23 15:16:23,189 WARN  [ io.ve.co.im.BlockedThreadChecker] (vertx-blocked-thread-checker) Thread Thread[vert.x-eventloop-thread-7,5,main] has been blocked for 5387 ms, time limit is 2000 ms: io.vertx.core.VertxException: Thread blocked
	at java.base/java.lang.Thread.start0(Native Method)
	at java.base/java.lang.Thread.start(Thread.java:1526)
	at org.jboss.threads.EnhancedQueueExecutor.doStartThread(EnhancedQueueExecutor.java:1752)
	at org.jboss.threads.EnhancedQueueExecutor.execute(EnhancedQueueExecutor.java:795)
	at io.quarkus.runtime.util.ForwardingExecutorService.execute(ForwardingExecutorService.java:22)
	at io.vertx.core.impl.ContextImpl.internalExecuteBlocking(ContextImpl.java:219)
	at io.vertx.core.impl.ContextImpl.executeBlocking(ContextImpl.java:175)
	at io.vertx.core.impl.DuplicatedContext.executeBlocking(DuplicatedContext.java:144)
	at io.quarkus.smallrye.health.runtime.QuarkusAsyncHealthCheckFactory$1.execute(QuarkusAsyncHealthCheckFactory.java:39)
	at io.smallrye.mutiny.operators.uni.UniRunSubscribeOn.subscribe(UniRunSubscribeOn.java:25)
	at io.smallrye.mutiny.operators.AbstractUni.subscribe(AbstractUni.java:36)
	at io.smallrye.mutiny.operators.uni.UniAndCombination$UniHandler.subscribe(UniAndCombination.java:233)
	at io.smallrye.mutiny.operators.uni.UniAndCombination$AndSupervisor.run(UniAndCombination.java:87)
	at io.smallrye.mutiny.operators.uni.UniAndCombination.subscribe(UniAndCombination.java:53)
	at io.smallrye.mutiny.operators.AbstractUni.subscribe(AbstractUni.java:36)
	at io.smallrye.mutiny.operators.uni.UniEmitOn.subscribe(UniEmitOn.java:22)
	at io.smallrye.mutiny.operators.AbstractUni.subscribe(AbstractUni.java:36)
	at io.smallrye.mutiny.groups.UniSubscribe.withSubscriber(UniSubscribe.java:51)
	at io.smallrye.mutiny.groups.UniSubscribe.with(UniSubscribe.java:110)
	at io.smallrye.mutiny.groups.UniSubscribe.with(UniSubscribe.java:88)
	at io.quarkus.smallrye.health.runtime.SmallRyeHealthHandlerBase.doHandle(SmallRyeHealthHandlerBase.java:54)
	at io.quarkus.smallrye.health.runtime.SmallRyeHealthHandlerBase.handle(SmallRyeHealthHandlerBase.java:35)
	at io.quarkus.smallrye.health.runtime.SmallRyeHealthHandlerBase.handle(SmallRyeHealthHandlerBase.java:23)
	at io.vertx.ext.web.impl.RouteState.handleContext(RouteState.java:1285)
	at io.vertx.ext.web.impl.RoutingContextImplBase.iterateNext(RoutingContextImplBase.java:177)
	at io.vertx.ext.web.impl.RoutingContextWrapper.next(RoutingContextWrapper.java:200)
	at io.vertx.ext.web.impl.RouterImpl.handleContext(RouterImpl.java:250)
	at io.vertx.ext.web.impl.RouteState.handleContext(RouteState.java:1285)
	at io.vertx.ext.web.impl.RoutingContextImplBase.iterateNext(RoutingContextImplBase.java:177)
	at io.vertx.ext.web.impl.RoutingContextImpl.next(RoutingContextImpl.java:140)
	at io.quarkus.vertx.http.runtime.VertxHttpRecorder$8.handle(VertxHttpRecorder.java:610)
	at io.quarkus.vertx.http.runtime.VertxHttpRecorder$8.handle(VertxHttpRecorder.java:604)
	at io.vertx.ext.web.impl.RouteState.handleContext(RouteState.java:1285)
	at io.vertx.ext.web.impl.RoutingContextImplBase.iterateNext(RoutingContextImplBase.java:177)
	at io.vertx.ext.web.impl.RoutingContextImpl.next(RoutingContextImpl.java:140)
	at io.quarkus.vertx.http.runtime.options.HttpServerCommonHandlers$1.handle(HttpServerCommonHandlers.java:62)
	at io.quarkus.vertx.http.runtime.options.HttpServerCommonHandlers$1.handle(HttpServerCommonHandlers.java:40)
	at io.vertx.ext.web.impl.RouteState.handleContext(RouteState.java:1285)
	at io.vertx.ext.web.impl.RoutingContextImplBase.iterateNext(RoutingContextImplBase.java:177)
	at io.vertx.ext.web.impl.RoutingContextImpl.next(RoutingContextImpl.java:140)
	at io.quarkus.resteasy.reactive.server.runtime.ResteasyReactiveRecorder$13.handle(ResteasyReactiveRecorder.java:358)
	at io.quarkus.resteasy.reactive.server.runtime.ResteasyReactiveRecorder$13.handle(ResteasyReactiveRecorder.java:347)
	at io.vertx.ext.web.impl.RouteState.handleContext(RouteState.java:1285)
	at io.vertx.ext.web.impl.RoutingContextImplBase.iterateNext(RoutingContextImplBase.java:177)
	at io.vertx.ext.web.impl.RoutingContextImpl.next(RoutingContextImpl.java:140)
	at io.quarkus.vertx.http.runtime.filters.accesslog.AccessLogHandler.handle(AccessLogHandler.java:164)
	at io.quarkus.vertx.http.runtime.filters.accesslog.AccessLogHandler.handle(AccessLogHandler.java:94)
	at io.vertx.ext.web.impl.RouteState.handleContext(RouteState.java:1285)
	at io.vertx.ext.web.impl.RoutingContextImplBase.iterateNext(RoutingContextImplBase.java:177)
	at io.vertx.ext.web.impl.RoutingContextImpl.next(RoutingContextImpl.java:140)
	at io.vertx.ext.web.impl.RouterImpl.handle(RouterImpl.java:68)
	at io.vertx.ext.web.impl.RouterImpl.handle(RouterImpl.java:37)
	at io.quarkus.vertx.http.runtime.VertxHttpRecorder$5.handle(VertxHttpRecorder.java:517)
	at io.quarkus.vertx.http.runtime.VertxHttpRecorder$5.handle(VertxHttpRecorder.java:514)
	at io.quarkus.vertx.http.runtime.options.HttpServerCommonHandlers$2.handle(HttpServerCommonHandlers.java:86)
	at io.quarkus.vertx.http.runtime.options.HttpServerCommonHandlers$2.handle(HttpServerCommonHandlers.java:69)
	at io.quarkus.vertx.http.runtime.VertxHttpRecorder$1.handle(VertxHttpRecorder.java:182)
	at io.quarkus.vertx.http.runtime.VertxHttpRecorder$1.handle(VertxHttpRecorder.java:158)
	at io.vertx.core.impl.ContextImpl.emit(ContextImpl.java:328)
	at io.vertx.core.impl.DuplicatedContext.emit(DuplicatedContext.java:164)
	at io.vertx.core.http.impl.Http1xServerConnection.handleMessage(Http1xServerConnection.java:174)
	at io.vertx.core.net.impl.ConnectionBase.read(ConnectionBase.java:159)
	at io.vertx.core.net.impl.VertxHandler.channelRead(VertxHandler.java:153)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:442)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420)
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412)
	at io.vertx.core.http.impl.Http1xUpgradeToH2CHandler.channelRead(Http1xUpgradeToH2CHandler.java:124)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:444)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420)
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412)
	at io.netty.handler.timeout.IdleStateHandler.channelRead(IdleStateHandler.java:289)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:442)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420)
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412)
	at io.netty.handler.codec.MessageToMessageDecoder.channelRead(MessageToMessageDecoder.java:103)
	at io.netty.handler.codec.MessageToMessageCodec.channelRead(MessageToMessageCodec.java:111)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:442)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420)
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412)
	at io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:346)
	at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:318)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:444)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420)
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412)
	at io.vertx.core.http.impl.Http1xOrH2CHandler.end(Http1xOrH2CHandler.java:61)
	at io.vertx.core.http.impl.Http1xOrH2CHandler.channelRead(Http1xOrH2CHandler.java:38)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:444)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420)
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412)
	at io.netty.handler.timeout.IdleStateHandler.channelRead(IdleStateHandler.java:289)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:442)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420)
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412)
	at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1407)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:440)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420)
	at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:918)
	at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:166)
	at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:788)
	at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:724)
	at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:650)
	at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:562)
	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 java.base/java.lang.Thread.run(Thread.java:1583)

@cescoffier
Copy link
Member

It's still making progress. In such a case, I would extend the Vert.x Thread checker timer.

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

No branches or pull requests
2 participants
@cescoffier @ncabanis