search

jetty / jetty.project

Eclipse Jetty® - Web Container & Clients - supports HTTP/2, HTTP/1.1, HTTP/1.0, websocket, servlets, and more
https://eclipse.dev/jetty
Other
3.86k stars 1.91k forks source link

ReadPendingException and then thread death #1047

Closed baldersheim closed 7 years ago

baldersheim commented 8 years ago

We are using ASYNC. Currently we are on jetty-9.3.13. When we run benchmarks we see a significant amount of ReadPendingException. So far I have seen 3 different stacktraces where 2 are originating from a jetty thread pool while one are from our threads. The stacktraces also come together with warnings from HttpConnection about "fill with unconsumed content!".

Stacktrace 1:

 Thu Oct 27 21:00:18 +0000 2016 perf7.head.factory.vespa.corp.bf1.yahoo.com 84492/710   container   Container.org.eclipse.jetty.server.HttpConnection   warning HttpConnection@4087bb37[SelectChannelEndPoint@2f7fdaec{/10.74.209.80:34198<->4080,Open,in,out,-,W,1/180000,HttpConnection@4087bb37}{io=0/0,kio=1,kro=1}][p=HttpParser{s=CHUNK,8171 of 0},g=HttpGenerator@743b970f{s=COMMITTED},c=HttpChannelOverHttp@49f90ea3{r=1,c=true,a=ASYNC_IO,uri=//perf7.head.factory.vespa.corp.bf1.yahoo.com:4080/reserved-for-internal-use/feedapi?&dataformat=XML_UTF8}] fill with unconsumed content!
Thu Oct 27 21:00:18 +0000 2016  perf8.head.factory.vespa.corp.bf1.yahoo.com 63713/710   container   Container.org.eclipse.jetty.server.HttpConnection   warning HttpConnection@26e190bb[SelectChannelEndPoint@5deb35b{/10.74.209.80:37036<->4080,Open,in,out,-,-,1/180000,HttpConnection@26e190bb}{io=0/0,kio=0,kro=1}][p=HttpParser{s=END,51562 of 0},g=HttpGenerator@3902c1bc{s=COMPLETING},c=HttpChannelOverHttp@4d84ceab{r=1,c=true,a=ASYNC_WAIT,uri=//perf8.head.factory.vespa.corp.bf1.yahoo.com:4080/reserved-for-internal-use/feedapi?&dataformat=XML_UTF8}] fill with unconsumed content!
Thu Oct 27 21:00:18 +0000 2016  perf8.head.factory.vespa.corp.bf1.yahoo.com 63713/710   container   Container.org.eclipse.jetty.io.FillInterest warning Read pending for AC.ReadCB@26e190bb{HttpConnection@26e190bb[SelectChannelEndPoint@5deb35b{/10.74.209.80:37036<->4080,CLOSED,ISHUT,OSHUT,-,-,0/180000,HttpConnection@26e190bb}{io=0/0,kio=-1,kro=-1}][p=HttpParser{s=CLOSED,0 of -1},g=HttpGenerator@3902c1bc{s=START},c=HttpChannelOverHttp@4d84ceab{r=1,c=false,a=IDLE,uri=null}]} prevented org.eclipse.jetty.server.HttpConnection$AsyncReadCallback@495a71ba
Thu Oct 27 21:00:18 +0000 2016  perf8.head.factory.vespa.corp.bf1.yahoo.com 63713/710   container   Container.org.eclipse.jetty.util.thread.QueuedThreadPool    warning 
exception=
java.nio.channels.ReadPendingException
\tat org.eclipse.jetty.io.FillInterest.register(FillInterest.java:72)
\tat org.eclipse.jetty.io.AbstractEndPoint.fillInterested(AbstractEndPoint.java:128)
\tat org.eclipse.jetty.server.HttpConnection.asyncReadFillInterested(HttpConnection.java:549)
\tat org.eclipse.jetty.server.HttpConnection$AsyncReadCallback.succeeded(HttpConnection.java:625)
\tat org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:95)
\tat org.eclipse.jetty.io.SelectChannelEndPoint$2.run(SelectChannelEndPoint.java:93)
\tat org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.executeProduceConsume(ExecuteProduceConsume.java:303)
\tat org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.produceConsume(ExecuteProduceConsume.java:148)
\tat org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.run(ExecuteProduceConsume.java:136)
\tat org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:671)
\tat org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:589)
\tat java.lang.Thread.run(Thread.java:745)
Thu Oct 27 21:00:18 +0000 2016  perf8.head.factory.vespa.corp.bf1.yahoo.com 63713/710   container   Container.org.eclipse.jetty.util.thread.QueuedThreadPool    warning Unexpected thread death: org.eclipse.jetty.util.thread.QueuedThreadPool$2@6ec1c07f in qtp1678557259{STARTED,8<=19<=200,i=7,q=0}
baldersheim commented 8 years ago

Stacktrace 2: This is the most frequent one.

Thu Oct 27 21:00:19 +0000 2016  perf8.head.factory.vespa.corp.bf1.yahoo.com 63713/780   container   Container.org.eclipse.jetty.io.FillInterest warning Read pending for org.eclipse.jetty.server.HttpConnection$AsyncReadCallback@dcfe1d1 prevented org.eclipse.jetty.server.HttpConnection$AsyncReadCallback@dcfe1d1
Thu Oct 27 21:00:19 +0000 2016  perf8.head.factory.vespa.corp.bf1.yahoo.com 63713/780   container   Container.org.eclipse.jetty.util.thread.QueuedThreadPool    warning 
exception=
java.nio.channels.ReadPendingException
\tat org.eclipse.jetty.io.FillInterest.register(FillInterest.java:72)
\tat org.eclipse.jetty.io.AbstractEndPoint.fillInterested(AbstractEndPoint.java:128)
\tat org.eclipse.jetty.server.HttpConnection.asyncReadFillInterested(HttpConnection.java:549)
\tat org.eclipse.jetty.server.HttpChannelOverHttp.asyncReadFillInterested(HttpChannelOverHttp.java:240)
\tat org.eclipse.jetty.server.HttpChannelState.unhandle(HttpChannelState.java:458)
\tat org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:487)
\tat org.eclipse.jetty.server.HttpChannel.run(HttpChannel.java:267)
\tat org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:671)
\tat org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:589)
\tat java.lang.Thread.run(Thread.java:745)
Thu Oct 27 21:00:19 +0000 2016  perf8.head.factory.vespa.corp.bf1.yahoo.com 63713/780   container   Container.org.eclipse.jetty.util.thread.QueuedThreadPool    warning Unexpected thread death: org.eclipse.jetty.util.thread.QueuedThreadPool$2@6ec1c07f in qtp1678557259{STARTED,8<=23<=200,i=12,q=0}
Thu Oct 27 21:00:19 +0000 2016  perf8.head.factory.vespa.corp.bf1.yahoo.com 63713/786   container   Container.org.eclipse.jetty.io.FillInterest warning Read pending for org.eclipse.jetty.server.HttpConnection$AsyncReadCallback@4e1917f2 prevented org.eclipse.jetty.server.HttpConnection$AsyncReadCallback@4e1917f2
Thu Oct 27 21:00:19 +0000 2016  perf8.head.factory.vespa.corp.bf1.yahoo.com 63713/784   container   Container.org.eclipse.jetty.io.FillInterest warning Read pending for org.eclipse.jetty.server.HttpConnection$AsyncReadCallback@37313daf prevented org.eclipse.jetty.server.HttpConnection$AsyncReadCallback@37313daf
baldersheim commented 8 years ago

And then the stacktraces from our threads. The first with ReadPendingException and the last with IllegalStateException Thu Oct 27 21:00:18 +0000 2016 perf8.head.factory.vespa.corp.bf1.yahoo.com 63713/728 container Container.org.eclipse.jetty.server.HttpConnection warning 

HttpConnection@3ab6f780[SelectChannelEndPoint@41db0c07{/10.74.209.80:37082<->4080,Open,in,out,-,-,0/180000,HttpConnection@3ab6f780}{io=0/0,kio=0,kro=1}][p=HttpParser{s=CHUNK,16342 of 0},g=HttpGenerator@12fe5c2d{s=COMMITTED},c=HttpChannelOverHttp@3e252664{r=1,c=true,a=ASYNC_IO,uri=//perf8.head.factory.vespa.corp.bf1.yahoo.com:4080/reserved-for-internal-use/feedapi?&dataformat=XML_UTF8}] fill with unconsumed content!
Thu Oct 27 21:00:18 +0000 2016  perf8.head.factory.vespa.corp.bf1.yahoo.com 63713/558   container   Container.org.eclipse.jetty.io.FillInterest warning Read pending for org.eclipse.jetty.server.HttpConnection$AsyncReadCallback@6b5dab55 prevented AC.ReadCB@3ab6f780{HttpConnection@3ab6f780[SelectChannelEndPoint@41db0c07{/10.74.209.80:37082<->4080,Open,in,out,FI,-,0/180000,HttpConnection@3ab6f780}{io=1/1,kio=1,kro=1}][p=HttpParser{s=START,0 of -1},g=HttpGenerator@12fe5c2d{s=START},c=HttpChannelOverHttp@3e252664{r=1,c=false,a=IDLE,uri=null}]}
Thu Oct 27 21:00:18 +0000 2016  perf8.head.factory.vespa.corp.bf1.yahoo.com 63713/558   container   Container.org.eclipse.jetty.server.HttpChannel  warning null
exception=
java.nio.channels.ReadPendingException
\tat org.eclipse.jetty.io.FillInterest.register(FillInterest.java:72)
\tat org.eclipse.jetty.io.AbstractEndPoint.fillInterested(AbstractEndPoint.java:128)
\tat org.eclipse.jetty.io.AbstractConnection.fillInterested(AbstractConnection.java:142)
\tat org.eclipse.jetty.server.HttpConnection.onCompleted(HttpConnection.java:441)
\tat org.eclipse.jetty.server.HttpChannel.onCompleted(HttpChannel.java:640)
\tat org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:454)
\tat org.eclipse.jetty.server.HttpChannel.run(HttpChannel.java:267)
\tat org.eclipse.jetty.server.handler.ContextHandler.handle(ContextHandler.java:1286)
\tat org.eclipse.jetty.server.HttpChannelState.runInContext(HttpChannelState.java:929)
\tat org.eclipse.jetty.server.HttpChannelState.complete(HttpChannelState.java:634)
\tat org.eclipse.jetty.server.AsyncContextState.complete(AsyncContextState.java:99)
\tat com.yahoo.jdisc.http.server.jetty.HttpRequestDispatch.lambda$new$12(HttpRequestDispatch.java:134)
\tat java.util.concurrent.CompletableFuture.uniWhenComplete(CompletableFuture.java:760)
\tat java.util.concurrent.CompletableFuture$UniWhenComplete.tryFire(CompletableFuture.java:736)
\tat java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:474)
\tat java.util.concurrent.CompletableFuture.complete(CompletableFuture.java:1962)
\tat com.yahoo.jdisc.http.server.jetty.ServletOutputStreamWriter.setFinished(ServletOutputStreamWriter.java:185)
\tat com.yahoo.jdisc.http.server.jetty.ServletOutputStreamWriter.writeBuffersInQueueToOutputStream(ServletOutputStreamWriter.java:163)
\tat com.yahoo.jdisc.http.server.jetty.ServletOutputStreamWriter.writeBuffer(ServletOutputStreamWriter.java:118)
\tat com.yahoo.jdisc.http.server.jetty.ServletOutputStreamWriter.close(ServletOutputStreamWriter.java:123)
\tat com.yahoo.jdisc.http.server.jetty.ServletResponseController$2.close(ServletResponseController.java:216)
\tat com.yahoo.jdisc.http.server.jetty.ReferenceCountingRequestHandler$ReferenceCountingContentChannel.close(ReferenceCountingRequestHandler.java:164)
\tat com.yahoo.container.jdisc.ThreadedHttpRequestHandler$LazyContentChannel.close(ThreadedHttpRequestHandler.java:177)
\tat com.yahoo.container.jdisc.ThreadedHttpRequestHandler.render(ThreadedHttpRequestHandler.java:127)
\tat com.yahoo.container.jdisc.ThreadedHttpRequestHandler.handleRequest(ThreadedHttpRequestHandler.java:82)
\tat com.yahoo.container.jdisc.ThreadedRequestHandler$RequestTask.processRequest(ThreadedRequestHandler.java:160)
\tat com.yahoo.container.jdisc.ThreadedRequestHandler$RequestTask.run(ThreadedRequestHandler.java:154)
\tat java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
\tat java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
\tat java.lang.Thread.run(Thread.java:745)
Thu Oct 27 21:00:19 +0000 2016  perf8.head.factory.vespa.corp.bf1.yahoo.com 63713/558   container   Container.com.yahoo.jdisc.http.server.jetty.HttpRequestDispatch warning async.complete failed
exception=
java.lang.IllegalStateException: s=IDLE i=true a=NOT_ASYNC
\tat org.eclipse.jetty.server.HttpChannelState.unhandle(HttpChannelState.java:380)
\tat org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:487)
\tat org.eclipse.jetty.server.HttpChannel.run(HttpChannel.java:267)
\tat org.eclipse.jetty.server.handler.ContextHandler.handle(ContextHandler.java:1286)
\tat org.eclipse.jetty.server.HttpChannelState.runInContext(HttpChannelState.java:929)
\tat org.eclipse.jetty.server.HttpChannelState.complete(HttpChannelState.java:634)
\tat org.eclipse.jetty.server.AsyncContextState.complete(AsyncContextState.java:99)
\tat com.yahoo.jdisc.http.server.jetty.HttpRequestDispatch.lambda$new$12(HttpRequestDispatch.java:134)
\tat java.util.concurrent.CompletableFuture.uniWhenComplete(CompletableFuture.java:760)
\tat java.util.concurrent.CompletableFuture$UniWhenComplete.tryFire(CompletableFuture.java:736)
\tat java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:474)
\tat java.util.concurrent.CompletableFuture.complete(CompletableFuture.java:1962)
\tat com.yahoo.jdisc.http.server.jetty.ServletOutputStreamWriter.setFinished(ServletOutputStreamWriter.java:185)
\tat com.yahoo.jdisc.http.server.jetty.ServletOutputStreamWriter.writeBuffersInQueueToOutputStream(ServletOutputStreamWriter.java:163)
\tat com.yahoo.jdisc.http.server.jetty.ServletOutputStreamWriter.writeBuffer(ServletOutputStreamWriter.java:118)
\tat com.yahoo.jdisc.http.server.jetty.ServletOutputStreamWriter.close(ServletOutputStreamWriter.java:123)
\tat com.yahoo.jdisc.http.server.jetty.ServletResponseController$2.close(ServletResponseController.java:216)
\tat com.yahoo.jdisc.http.server.jetty.ReferenceCountingRequestHandler$ReferenceCountingContentChannel.close(ReferenceCountingRequestHandler.java:164)
\tat com.yahoo.container.jdisc.ThreadedHttpRequestHandler$LazyContentChannel.close(ThreadedHttpRequestHandler.java:177)
\tat com.yahoo.container.jdisc.ThreadedHttpRequestHandler.render(ThreadedHttpRequestHandler.java:127)
\tat com.yahoo.container.jdisc.ThreadedHttpRequestHandler.handleRequest(ThreadedHttpRequestHandler.java:82)
\tat com.yahoo.container.jdisc.ThreadedRequestHandler$RequestTask.processRequest(ThreadedRequestHandler.java:160)
\tat com.yahoo.container.jdisc.ThreadedRequestHandler$RequestTask.run(ThreadedRequestHandler.java:154)
\tat java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
\tat java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
\tat java.lang.Thread.run(Thread.java:745)
baldersheim commented 8 years ago

I have tested 9.3.8 - 9.3.13. All have similar errors. However prior to 9.3.13 we also saw issues during write that seem related to fixes you did on early eof handling and the bytebufferpool.

When we used the default ByteBufferPool we saw a lot of issues with BufferOverflow etc in addition. After just providing simple ByteBufferPool that does not recycle any buffers these issues went away.

I have not seen anything on this subject anywhere so I thought I would try to get some help here. The first I need to figure out is if we are using the interfaces wrong. If that is not obvious, how do we go about to narrow it down.

gregw commented 8 years ago

@baldersheim it is a bit hard to read your stack traces. Can you use mark down to format (see below without the >:

>```
>some pasted exception
>  at somewhere
>  at elsewhere
>```

The first thing to work out is if there really is a pending read? Does your code call isReady() and get a false return, then perhaps try another async operations (dispatch? complete? timeout?) before the callback to onDataAvailable?

If you could give us either the code you use for async IO or an outline of it, that would be helpful.

thanks

gregw commented 8 years ago

Looking at the exceptions again, I can see that complete is being called, so I'm guessing you are doing that while the input is unready - ie it has received false from an isReady call and onDataAvailable has yet to be called.

So I'm suspecting a problem with your application - you will need to let the async IO timeout or complete before trying to complete the async lifecycle.... however EVEN if it is your app, I think we could give a much better error message.

So I'd still like to work on a reliable reproduction and then fix your app and/or our error handling.

bjorncs commented 8 years ago

The Servlet 3.1 specification states the following about the AsyncContext.complete():

My interpretation of the spec is that complete can be called anytime. Our implementation is based on that assumption (complete is invoked sometime after close on ServletOutputStream/ServletInputStream).

sbordet commented 8 years ago

@bjorncs if you use blocking writes, then you calls to AsyncContext.complete() will probably happen after you fully read or fully wrote, and so they are ok.

However, an application that does async read or async writes must check that the reads and the writes are finished before calling complete().

This code is wrong:

public void onWritePossible() {
    response.getOutputStream().write("data".getBytes("UTF-8"));
    asyncContext.complete();
}

It is wrong because there is no guarantee that the write is complete, so you cannot call AsyncContext.complete(). Correct code is:

public void onWritePossible() {
    ServletOutputStream out = response.getOutputStream();
    if (!writing) {
        out.write("data".getBytes("UTF-8"));
        writing = true;
    }
    if (out.isReady()) {
        writing = false;
        asyncContext.complete();
    }
}

If out.isReady() returns false, onWritePossible() will be called again when the write has completed.

I believe this is the accepted interpretation of the spec for async I/O, and the spec needs an erratum related to the paragraphs you quoted, since it's not really at any time, it's more "at any time with no pending I/O". @gregw wdyt ?

sbordet commented 8 years ago

You can have a look at the slides and video (part1, part2) of the Servlet 3.1 gotchas.

@baldersheim let know if you hit one of the gotchas :wink:

baldersheim commented 8 years ago

Thanks, alot. We have gotten very good feedback. I think the we should in theory have tried to accomplish what you wrote in your last example. However we will go through our integration again and add some verification of that.

If not we will narrow it down and produce a unit test that will trigger this. Hopefully we will get to the bottom of this next week :)

baldersheim commented 8 years ago

Forgot to memotion that this is http 1.1 with persistent connections.

bjorncs commented 8 years ago

Hi again. We have gone through our Servlet async integration and verified that both ServletInputStream.isReady() and ServletOutputStream.isReady() returns true before invoking AsyncContext.complete(). The call to complete() happens either in a Jetty thread or non-Jetty thread depending on whether our response or request processing completes first. We have only seen these Jetty errors during heavy load (with POST requests from multiple simultaneously clients). We have seen the same behaviour in 9.3.14.

sbordet commented 8 years ago

All right, if you call complete() properly, we need a reproducible test case, because our test suite works and CometD works, etc. Perhaps you're hitting an edge case, and so we need to know the details.

At minimum we would need you to attach the full server DEBUG logs, along with the code (or pseudo code, to understand what your application does). If you can attach a reproducible test case, will be even better.

bjorncs commented 8 years ago

A few questions; is it safe to call ServletOutputStream.setWriteListener() from a non-Jetty thread? Similarly with ServletOutputStream.setWriteListener(), is it safe to call ServletOutputStream.isReady() outside onWritePossible to register for WriteListener callback? In https://github.com/eclipse/jetty.project/issues/997 it is stated that setReadListener must be called from the same thread as startAsync(). Does this apply for setWriteListener as well?

sbordet commented 8 years ago

is it safe to call ServletOutputStream.setWriteListener() from a non-Jetty thread?

Yes, it should be possible. Issues #997 and #1074 are about ServletInputStream.

is it safe to call ServletOutputStream.isReady() outside onWritePossible() to register for WriteListener callback?

That's quite convoluted. I think you can only call isReady() after you have set the WriteListener, but yes it can be called from any threads (for example, you can call it from an input callback such as onDataAvailable()).

bjorncs commented 8 years ago

See https://github.com/bjorncs/jetty.project/commit/c22d1cd6eab3466cee2a9299204ecf044dbb4f30 for example code triggering ReadPendingException. Setting the WriterListener in a non-Jetty thread triggers the exception (https://github.com/bjorncs/jetty.project/commit/c22d1cd6eab3466cee2a9299204ecf044dbb4f30/examples/embedded/src/main/java/org/eclipse/jetty/embedded/Bug.java#L108-109). We have been unable to reliably trigger the filled with unconsumed content error in that example, but by assigning the write listener in the Jetty thread the warning seems to go away.

The example is using multiple clients sending large chunked requests, with the chunks sent over a longer timespan of a tens of milliseconds.

bjorncs commented 7 years ago

We were able to work around the bug by registering the write listener in the same thread that called ASyncContext.startAsync() and registered the read listener. The workaround has some performance degradation in certain scenarios and we plan to remove it once the Jetty bug is fixed.

sbordet commented 7 years ago

@gregw please review the fix.