geoand
commented
4 years ago @johnaohara have you seen anything similar?
Closed yuhaibohotmail closed 4 years ago
geoand
commented
4 years ago @johnaohara have you seen anything similar?
johnaohara
commented
4 years ago @geoand looks similar to #4173
geoand
commented
4 years ago Which was fixed however
johnaohara
commented
4 years ago @geoand Does your reproducer fail for master now? (https://github.com/geoand/quarkus-vertx-threads-blocked)
geoand
commented
4 years ago Let me check
johnaohara
commented
4 years ago Have just re-run against 1.0.0.CR1 and is working as expected
geoand
commented
4 years ago I just ran it my reproducer against master and it worked just fine.
johnaohara
commented
4 years ago I looks like there is a race condition in request.response().drainHandler(). I have opened a pr #5451.
yuhaibohotmail
commented
4 years ago @johnaohara I've simplified my program and can reproduce it in several of my environments.
My endpoint:
@Path("/hello")
public class ExampleResource {
@GET
@Produces(MediaType.TEXT_PLAIN)
public String hello() {
StringBuffer buffer = new StringBuffer();
try {
Thread.sleep(10);
} catch (InterruptedException e) {
e.printStackTrace();
}
buffer.append("[");
for(int i = 0 ;i <1000;i++ ) {
buffer.append("{\"id\":1,\"name\":\"tom\",\"sex\":\"f\",\"testCode\":\"12345\"},");
}
buffer.append("{\"id\":1,\"name\":\"tom\",\"sex\":\"f\",\"testCode\":\"12345\"} ]");
return buffer.toString();
}
}Run wrk
[root@localhost wrk]# wrk -t20 -c2000 -d30s http://localhost:8888/hello
Running 30s test @ http://localhost:8888/hello
20 threads and 2000 connections
Thread Stats Avg Stdev Max +/- Stdev
Latency 652.20ms 95.72ms 1.03s 79.64%
Req/Sec 180.39 180.45 0.99k 85.29%
37192 requests in 30.10s, 1.74GB read
Socket errors: connect 999, read 0, write 0, timeout 0
Requests/sec: 1235.66
Transfer/sec: 59.21MBWhen the wrk is running, the endpoint can be accessed through the browser.
Once the wrk is finished, the program reports some exception and then does not respond to the request.
2019-11-14 03:32:42,126 INFO [io.quarkus] (main) load-test 1.0.0-SNAPSHOT (running on Quarkus 1.0.0.CR1) started in 1.222s. Listening on: http://0.0.0.0:8888
2019-11-14 03:32:42,146 INFO [io.quarkus] (main) Profile prod activated.
2019-11-14 03:32:42,146 INFO [io.quarkus] (main) Installed features: [cdi, resteasy]
2019-11-14 03:33:16,424 SEVERE [io.ver.cor.imp.ContextImpl] (vert.x-eventloop-thread-0) Unhandled exception: java.lang.IllegalMonitorStateException
at java.lang.Object.notify(Native Method)
at io.quarkus.resteasy.runtime.standalone.VertxBlockingOutput$1.handle(VertxBlockingOutput.java:34)
at io.quarkus.resteasy.runtime.standalone.VertxBlockingOutput$1.handle(VertxBlockingOutput.java:25)
at io.vertx.core.http.impl.HttpServerResponseImpl.handleClosed(HttpServerResponseImpl.java:616)
at io.vertx.core.http.impl.HttpServerResponseImpl.handleException(HttpServerResponseImpl.java:590)
at io.vertx.core.http.impl.HttpServerRequestImpl.handleException(HttpServerRequestImpl.java:577)
at io.vertx.core.http.impl.Http1xServerConnection.handleClosed(Http1xServerConnection.java:413)
at io.vertx.core.net.impl.VertxHandler.lambda$channelInactive$4(VertxHandler.java:162)
at io.vertx.core.impl.ContextImpl.executeTask(ContextImpl.java:369)
at io.vertx.core.impl.EventLoopContext.execute(EventLoopContext.java:43)
at io.vertx.core.impl.ContextImpl.executeFromIO(ContextImpl.java:232)
at io.vertx.core.impl.ContextImpl.executeFromIO(ContextImpl.java:224)
at io.vertx.core.net.impl.VertxHandler.channelInactive(VertxHandler.java:162)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:257)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:243)
at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:236)
at io.netty.handler.codec.ByteToMessageDecoder.channelInputClosed(ByteToMessageDecoder.java:393)
at io.netty.handler.codec.ByteToMessageDecoder.channelInactive(ByteToMessageDecoder.java:358)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:257)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:243)
at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:236)
at io.netty.channel.DefaultChannelPipeline$HeadContext.channelInactive(DefaultChannelPipeline.java:1417)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:257)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:243)
at io.netty.channel.DefaultChannelPipeline.fireChannelInactive(DefaultChannelPipeline.java:913)
at io.netty.channel.AbstractChannel$AbstractUnsafe$8.run(AbstractChannel.java:819)
at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:163)
at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:510)
at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:518)
at io.netty.util.concurrent.SingleThreadEventExecutor$6.run(SingleThreadEventExecutor.java:1044)
at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
at java.lang.Thread.run(Thread.java:748)
2019-11-14 03:33:16,425 SEVERE [io.ver.cor.imp.ContextImpl] (vert.x-eventloop-thread-0) Unhandled exception: java.lang.IllegalMonitorStateException
at java.lang.Object.notify(Native Method)
at io.quarkus.resteasy.runtime.standalone.VertxBlockingOutput$1.handle(VertxBlockingOutput.java:34)source code load-test.zip
johnaohara
commented
4 years ago @yuhaibohotmail thanks a lot for the reproducer, I will use it to test a potential fix.
johnaohara
commented
4 years ago @yuhaibohotmail what hardware are you running on? I am not reproducing the error on my local machine, but will also test in our lab
johnaohara
commented
4 years ago I can re-create now
yuhaibohotmail
commented
4 years ago @johnaohara Can you reproduce it now？
I tested it in two environments.
johnaohara
commented
4 years ago @yuhaibohotmail I have your test running without hanging the application. Now waiting on CI and approval for the PR. Thanks
johnaohara
commented
4 years ago @yuhaibohotmail #5451 fixes this issue and will be included in the next release. Thank you for your help
Describe the bug (Describe the problem clearly and concisely.)
I did a simple stress test，then the program keeps giving alarm log.
After the test ,All requests are unresponsive . jstack log:
Expected behavior (Describe the expected behavior clearly and concisely.)
Actual behavior (Describe the actual behavior clearly and concisely.)
To Reproduce Steps to reproduce the behavior:
Configuration
Screenshots (If applicable, add screenshots to help explain your problem.)
Environment (please complete the following information):
Output of
uname -aorver:Linux ***** 3.10.0-862.3.3.el7.x86_64 #1 SMP Fri Jun 15 04:15:27 UTC 2018 x86_64 x86_64 x86_64 GNU/Linux
Output of
java -version: java version "1.8.0_201" Java(TM) SE Runtime Environment (build 1.8.0_201-b09) Java HotSpot(TM) 64-Bit Server VM (build 25.201-b09, mixed mode)GraalVM version (if different from Java):
Quarkus version or git rev: 1.0.0.CR1
Additional context
The full jstack dump info jstack-l.txt