Re: Non-Blocking IO Write Issue
On Dec 23, 2013, at 7:55 PM, David Bullock david.bull...@machaira.com.au wrote: On 24 December 2013 07:58, Daniel Mikusa dmik...@gopivotal.com wrote: On Dec 19, 2013, at 8:08 PM, David Bullock david.bull...@machaira.com.au wrote: On 20 December 2013 04:10, Daniel Mikusa dmik...@gopivotal.com wrote: Unfortunately, once this problem starts to occur onWritePossible doesn't get called back. When I take a thread dump of the code, it just shows all of the threads doing nothing. Increasing timeout doesn't seem to help. Failures still occur within the same timeframe (i.e. same number requests to the server). The only affect is to create a delay between when requests stop being processed and the stack trace shows up. What happens if you instead pass the ServletOutputStream to the DataStreamWriteListener's constructor? Unfortunately nothing. I still see the issue. OK, new theory. At some point, something happens in your onWritePossible handler which throws an unchecked exception and crashes the Tomcat thread which is responsible for keeping track of which async servlets are still wanting to write data and doing appropriate cleanup of the NIO selectors/keys. When onWritePossible is called by Tomcat, it's wrapped in a try..catch..finally, which catches Throwable. If it catches something, the write listener's onError method should get called with the exception. That's not happening in my unit test, so it doesn't seem like an exception is being raised in onWritePossible. See around line 369. http://svn.apache.org/viewvc/tomcat/trunk/java/org/apache/catalina/connector/CoyoteAdapter.java?view=markup My money would have been on calling getOutputStream() on the response a second time (it throws java.lang.IllegalStateException, which is unchecked), but you say you got rid of that. As far as I can tell, you should be able to call getOutputStream() as many times as you want. According to the javadoc, it only throws IllegalStateException if you've called getWriter() and then call getOutputStream(). http://tomcat.apache.org/tomcat-8.0-doc/servletapi/javax/servlet/ServletResponse.html#getOutputStream() To eliminate other unchecked candidates, make your onWritePossible() catch java.lang.Throwable and emit appropriate log messages if it catches anything (or more usefully, point a debugger at the catch clause). Tried this. Unfortunately, it does not catch anything. If that doesn't yield success, then I would like to see 2 thread dumps - once when onWritePossible() has been called (maybe put in a Thread.sleep(5000) so you have time to tickle the JVM), Here's a thread dump from the unit test, which I've paused in the debugger during the first call to the onWritePossible method. 2013-12-29 09:07:04 Full thread dump Java HotSpot(TM) 64-Bit Server VM (24.45-b08 mixed mode): http-nio-127.0.0.1-auto-1-exec-1 daemon prio=5 tid=0x7fde4b888000 nid=0x8403 at breakpoint[0x0001965b4000] java.lang.Thread.State: RUNNABLE at org.apache.catalina.nonblocking.TestWriteListener$DataStreamingServlet$DataStreamWriteListener.onWritePossible(TestWriteListener.java:114) at org.apache.coyote.Response.onWritePossible(Response.java:658) at org.apache.catalina.connector.CoyoteAdapter.asyncDispatch(CoyoteAdapter.java:369) at org.apache.coyote.http11.AbstractHttp11Processor.asyncDispatch(AbstractHttp11Processor.java:1618) at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:631) at org.apache.coyote.http11.Http11NioProtocol$Http11ConnectionHandler.process(Http11NioProtocol.java:223) at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1576) at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1534) - locked 0x000165068000 (a org.apache.tomcat.util.net.NioChannel) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) at java.lang.Thread.run(Thread.java:744) http-nio-127.0.0.1-auto-1-Acceptor-0 daemon prio=5 tid=0x7fde4f07e000 nid=0x8203 runnable [0x000197303000] java.lang.Thread.State: RUNNABLE at sun.nio.ch.ServerSocketChannelImpl.accept0(Native Method) at sun.nio.ch.ServerSocketChannelImpl.accept(ServerSocketChannelImpl.java:241) - locked 0x000165018110 (a java.lang.Object) at org.apache.tomcat.util.net.NioEndpoint$Acceptor.run(NioEndpoint.java:693) at java.lang.Thread.run(Thread.java:744) http-nio-127.0.0.1-auto-1-ClientPoller-1 daemon prio=5 tid=0x7fde4b89f800 nid=0x8003 runnable [0x000197124000] java.lang.Thread.State: RUNNABLE at sun.nio.ch.KQueueArrayWrapper.kevent0(Native Method) at sun.nio.ch.KQueueArrayWrapper.poll(KQueueArrayWrapper.java:200)
Re: Non-Blocking IO Write Issue
Well, the states of those threads look normal enough. Definitely not a resource starvation issue (which is what it 'feels' like). I guess some values are getting lost somewhere. Just looking at the stacktrace for the onWritePossible() example though ... I'm not able to trace the same execution path through the version of the Tomcat trunk, except by going back some weeks/months. For example, with: http-nio-127.0.0.1-auto-1-exec-1 daemon prio=5 tid=0x7fde4b888000 nid=0x8403 at breakpoint[0x0001965b4000] java.lang.Thread.State: RUNNABLE at org.apache.catalina.nonblocking.TestWriteListener$DataStreamingServlet$DataStreamWriteListener.onWritePossible(TestWriteListener.java:114) at org.apache.coyote.Response.onWritePossible(Response.java:658) at org.apache.catalina.connector.CoyoteAdapter.asyncDispatch(CoyoteAdapter.java:369) at org.apache.coyote.http11.AbstractHttp11Processor.asyncDispatch(AbstractHttp11Processor.java:1618) ... well, the AbstractHttp11Processor.asyncDispatch() method seems to have been refactored out in May, earlier this year: http://svn.apache.org/viewvc/tomcat/trunk/java/org/apache/coyote/http11/Http11NioProcessor.java?r1=1478576r2=1478714diff_format=h Reading the source code and the repository, it seems there has been a *lot* of activity around this async stuff in the codebase, and you may well get different test results with a more modern version of the trunk. cheers, David. David Bullock Machaira Enterprises Pty Ltd PO Box 31 Canowindra NSW 2804 02 6344 1100 http://machaira.com.au/ On 30 December 2013 01:21, Daniel Mikusa dmik...@gopivotal.com wrote: On Dec 23, 2013, at 7:55 PM, David Bullock david.bull...@machaira.com.au wrote: On 24 December 2013 07:58, Daniel Mikusa dmik...@gopivotal.com wrote: On Dec 19, 2013, at 8:08 PM, David Bullock david.bull...@machaira.com.au wrote: On 20 December 2013 04:10, Daniel Mikusa dmik...@gopivotal.com wrote: Unfortunately, once this problem starts to occur onWritePossible doesn't get called back. When I take a thread dump of the code, it just shows all of the threads doing nothing. Increasing timeout doesn't seem to help. Failures still occur within the same timeframe (i.e. same number requests to the server). The only affect is to create a delay between when requests stop being processed and the stack trace shows up. What happens if you instead pass the ServletOutputStream to the DataStreamWriteListener's constructor? Unfortunately nothing. I still see the issue. OK, new theory. At some point, something happens in your onWritePossible handler which throws an unchecked exception and crashes the Tomcat thread which is responsible for keeping track of which async servlets are still wanting to write data and doing appropriate cleanup of the NIO selectors/keys. When onWritePossible is called by Tomcat, it's wrapped in a try..catch..finally, which catches Throwable. If it catches something, the write listener's onError method should get called with the exception. That's not happening in my unit test, so it doesn't seem like an exception is being raised in onWritePossible. See around line 369. http://svn.apache.org/viewvc/tomcat/trunk/java/org/apache/catalina/connector/CoyoteAdapter.java?view=markup My money would have been on calling getOutputStream() on the response a second time (it throws java.lang.IllegalStateException, which is unchecked), but you say you got rid of that. As far as I can tell, you should be able to call getOutputStream() as many times as you want. According to the javadoc, it only throws IllegalStateException if you've called getWriter() and then call getOutputStream(). http://tomcat.apache.org/tomcat-8.0-doc/servletapi/javax/servlet/ServletResponse.html#getOutputStream() To eliminate other unchecked candidates, make your onWritePossible() catch java.lang.Throwable and emit appropriate log messages if it catches anything (or more usefully, point a debugger at the catch clause). Tried this. Unfortunately, it does not catch anything. If that doesn't yield success, then I would like to see 2 thread dumps - once when onWritePossible() has been called (maybe put in a Thread.sleep(5000) so you have time to tickle the JVM), Here's a thread dump from the unit test, which I've paused in the debugger during the first call to the onWritePossible method. 2013-12-29 09:07:04 Full thread dump Java HotSpot(TM) 64-Bit Server VM (24.45-b08 mixed mode): http-nio-127.0.0.1-auto-1-exec-1 daemon prio=5 tid=0x7fde4b888000 nid=0x8403 at breakpoint[0x0001965b4000] java.lang.Thread.State: RUNNABLE at org.apache.catalina.nonblocking.TestWriteListener$DataStreamingServlet$DataStreamWriteListener.onWritePossible(TestWriteListener.java:114) at org.apache.coyote.Response.onWritePossible(Response.java:658) at
Re: Non-Blocking IO Write Issue
On Dec 29, 2013, at 11:45 AM, David Bullock david.bull...@machaira.com.au wrote: Well, the states of those threads look normal enough. Definitely not a resource starvation issue (which is what it 'feels' like). I guess some values are getting lost somewhere. Just looking at the stacktrace for the onWritePossible() example though ... I'm not able to trace the same execution path through the version of the Tomcat trunk, except by going back some weeks/months. For example, with: http-nio-127.0.0.1-auto-1-exec-1 daemon prio=5 tid=0x7fde4b888000 nid=0x8403 at breakpoint[0x0001965b4000] java.lang.Thread.State: RUNNABLE at org.apache.catalina.nonblocking.TestWriteListener$DataStreamingServlet$DataStreamWriteListener.onWritePossible(TestWriteListener.java:114) at org.apache.coyote.Response.onWritePossible(Response.java:658) at org.apache.catalina.connector.CoyoteAdapter.asyncDispatch(CoyoteAdapter.java:369) at org.apache.coyote.http11.AbstractHttp11Processor.asyncDispatch(AbstractHttp11Processor.java:1618) ... well, the AbstractHttp11Processor.asyncDispatch() method seems to have been refactored out in May, earlier this year: http://svn.apache.org/viewvc/tomcat/trunk/java/org/apache/coyote/http11/Http11NioProcessor.java?r1=1478576r2=1478714diff_format=h Reading the source code and the repository, it seems there has been a *lot* of activity around this async stuff in the codebase, and you may well get different test results with a more modern version of the trunk. I would agree that there have been lots of updates, but I am running that latest update from svn. $ svn update At revision 1554057. Just to make sure Eclipse wasn't doing something weird. I did a clean on the project and watched it rebuild everything. Looking at the stack trace, I'm seeing line numbers that correspond to the correct line numbers when I view the subversion repository in my browser, so I believe it's running with the latest code. Also I'm able to trace through the code by the file / line number reported in the stack trace. Thanks for the suggestions, but at this point I'm reasonably confident I haven't missed something simple so I've gone ahead and created a bug report. https://issues.apache.org/bugzilla/show_bug.cgi?id=55939 Dan cheers, David. David Bullock Machaira Enterprises Pty Ltd PO Box 31 Canowindra NSW 2804 02 6344 1100 http://machaira.com.au/ On 30 December 2013 01:21, Daniel Mikusa dmik...@gopivotal.com wrote: On Dec 23, 2013, at 7:55 PM, David Bullock david.bull...@machaira.com.au wrote: On 24 December 2013 07:58, Daniel Mikusa dmik...@gopivotal.com wrote: On Dec 19, 2013, at 8:08 PM, David Bullock david.bull...@machaira.com.au wrote: On 20 December 2013 04:10, Daniel Mikusa dmik...@gopivotal.com wrote: Unfortunately, once this problem starts to occur onWritePossible doesn't get called back. When I take a thread dump of the code, it just shows all of the threads doing nothing. Increasing timeout doesn't seem to help. Failures still occur within the same timeframe (i.e. same number requests to the server). The only affect is to create a delay between when requests stop being processed and the stack trace shows up. What happens if you instead pass the ServletOutputStream to the DataStreamWriteListener's constructor? Unfortunately nothing. I still see the issue. OK, new theory. At some point, something happens in your onWritePossible handler which throws an unchecked exception and crashes the Tomcat thread which is responsible for keeping track of which async servlets are still wanting to write data and doing appropriate cleanup of the NIO selectors/keys. When onWritePossible is called by Tomcat, it's wrapped in a try..catch..finally, which catches Throwable. If it catches something, the write listener's onError method should get called with the exception. That's not happening in my unit test, so it doesn't seem like an exception is being raised in onWritePossible. See around line 369. http://svn.apache.org/viewvc/tomcat/trunk/java/org/apache/catalina/connector/CoyoteAdapter.java?view=markup My money would have been on calling getOutputStream() on the response a second time (it throws java.lang.IllegalStateException, which is unchecked), but you say you got rid of that. As far as I can tell, you should be able to call getOutputStream() as many times as you want. According to the javadoc, it only throws IllegalStateException if you've called getWriter() and then call getOutputStream(). http://tomcat.apache.org/tomcat-8.0-doc/servletapi/javax/servlet/ServletResponse.html#getOutputStream() To eliminate other unchecked candidates, make your onWritePossible() catch java.lang.Throwable and emit appropriate log messages if it catches anything (or more usefully, point a debugger at the catch clause). Tried this.
Re: Non-Blocking IO Write Issue
On Dec 19, 2013, at 8:08 PM, David Bullock david.bull...@machaira.com.au
wrote:
On 20 December 2013 04:10, Daniel Mikusa dmik...@gopivotal.com wrote:
When run, you'll see that it processes some of the requests but fails due to
a timeout. I've not been able to replicate the other exceptions with the
unit test though, so those may be unrelated.
@WebServlet(asyncSupported = true)
public class DataStreamingServlet extends HttpServlet {
@Override
protected void service(HttpServletRequest request,
HttpServletResponse response) throws ServletException, IOException
{
...
DataStreamWriteListener dswl = new
DataStreamWriteListener(asyncContext, blocks);
response.getOutputStream().setWriteListener(dswl);
}
private class DataStreamWriteListener implements WriteListener {
@Override
public void onWritePossible() throws IOException {
ServletOutputStream output =
context.getResponse().getOutputStream();
Any thoughts on what's happening here?
This is a total guess ... getOutputStream() is waiting on a lock it
will never acquire?
No, it's non-blocking IO so it wouldn't (definitely shouldn't) wait here.
Instead it writes until it's told that it cannot write (output.isReady() ==
false) without blocking. At that point, the container is supposed to call my
code (onWritePossible) once it can write again. Unfortunately, once this
problem starts to occur onWritePossible doesn't get called back.
I did a little more testing and for requests that timeout, it does not appear
that onWritePossible ever gets called. I added some logging to the code to
indicate when it first calls onWritePossible, when it must wait to write more
data and when it's done writing data. While the test is warming up and the
requests are being processed OK, I see all three log statements. Once the
problem manifests, new requests do not trigger any logging. They just timeout
and continue to timeout until I restart the JVM.
(Increase the timeout, do a thread-dump).
When I take a thread dump of the code, it just shows all of the threads doing
nothing. Increasing timeout doesn't seem to help. Failures still occur within
the same timeframe (i.e. same number requests to the server). The only affect
is to create a delay between when requests stop being processed and the stack
trace shows up.
What happens if you instead pass the ServletOutputStream to the
DataStreamWriteListener's constructor?
Unfortunately nothing. I still see the issue.
Thanks
Dan
cheers,
David.
-
To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org
For additional commands, e-mail: users-h...@tomcat.apache.org
-
To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org
For additional commands, e-mail: users-h...@tomcat.apache.org
Re: Non-Blocking IO Write Issue
On 24 December 2013 07:58, Daniel Mikusa dmik...@gopivotal.com wrote: On Dec 19, 2013, at 8:08 PM, David Bullock david.bull...@machaira.com.au wrote: On 20 December 2013 04:10, Daniel Mikusa dmik...@gopivotal.com wrote: Unfortunately, once this problem starts to occur onWritePossible doesn't get called back. When I take a thread dump of the code, it just shows all of the threads doing nothing. Increasing timeout doesn't seem to help. Failures still occur within the same timeframe (i.e. same number requests to the server). The only affect is to create a delay between when requests stop being processed and the stack trace shows up. What happens if you instead pass the ServletOutputStream to the DataStreamWriteListener's constructor? Unfortunately nothing. I still see the issue. OK, new theory. At some point, something happens in your onWritePossible handler which throws an unchecked exception and crashes the Tomcat thread which is responsible for keeping track of which async servlets are still wanting to write data and doing appropriate cleanup of the NIO selectors/keys. My money would have been on calling getOutputStream() on the response a second time (it throws java.lang.IllegalStateException, which is unchecked), but you say you got rid of that. To eliminate other unchecked candidates, make your onWritePossible() catch java.lang.Throwable and emit appropriate log messages if it catches anything (or more usefully, point a debugger at the catch clause). If that doesn't yield success, then I would like to see 2 thread dumps - once when onWritePossible() has been called (maybe put in a Thread.sleep(5000) so you have time to tickle the JVM), and once when it is in the failure state. (one in the starting-to-fail state would be good too). cheers, David. - To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org For additional commands, e-mail: users-h...@tomcat.apache.org
Non-Blocking IO Write Issue
I have a simple servlet which I'm running on Tomcat 8 trunk with Java 7. It's
using a non-blocking IO WriteListener to write 8k blocks of static data to the
response. The number of blocks it will write is given as a request parameter.
When I start out making individual requests to the server (1-1000 blocks)
things are fine and those are handled without a problem. However once I start
to send multiple requests using JMeter, requests begin to fail. It starts
slowly with only a few requests failing and then proceeds to the point where
every request fails. At that point, Tomcat will serve JSP pages and Servlets
that use blocking IO, but it will not serve any requests that use the
non-blocking IO apis (ReadListener / WriteListener). If I try to hit the byte
counter servlet or number writer servlet included in the examples then my
browser will timeout or display the error java.lang.IllegalStateException:
getOutputStream() has already been called for this response.
In my tests most of the time the requests fail because the async context times
out, but occasionally (one or two times out of 100) I'll see these exceptions.
1.) org.apache.catalina.connector.ClientAbortException: java.io.IOException:
Key must be cancelled
at
org.apache.catalina.connector.OutputBuffer.realWriteBytes(OutputBuffer.java:396)
at org.apache.tomcat.util.buf.ByteChunk.append(ByteChunk.java:315)
at
org.apache.catalina.connector.OutputBuffer.writeBytes(OutputBuffer.java:421)
at
org.apache.catalina.connector.OutputBuffer.write(OutputBuffer.java:409)
at
org.apache.catalina.connector.CoyoteOutputStream.write(CoyoteOutputStream.java:97)
at
org.apache.catalina.connector.CoyoteOutputStream.write(CoyoteOutputStream.java:90)
at
com.pivotal.demos.nbio.DataStreamerNbioServlet$2.onWritePossible(DataStreamerNbioServlet.java:64)
at org.apache.coyote.Response.onWritePossible(Response.java:655)
at
org.apache.catalina.connector.CoyoteAdapter.asyncDispatch(CoyoteAdapter.java:369)
at
org.apache.coyote.http11.AbstractHttp11Processor.asyncDispatch(AbstractHttp11Processor.java:1618)
at
org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:631)
at
org.apache.coyote.http11.Http11NioProtocol$Http11ConnectionHandler.process(Http11NioProtocol.java:223)
at
org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1576)
at
org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1534)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:744)
Caused by: java.io.IOException: Key must be cancelled
at
org.apache.coyote.http11.InternalNioOutputBuffer.writeToSocket(InternalNioOutputBuffer.java:131)
at
org.apache.coyote.http11.InternalNioOutputBuffer.addToBB(InternalNioOutputBuffer.java:198)
at
org.apache.coyote.http11.InternalNioOutputBuffer.access$000(InternalNioOutputBuffer.java:42)
at
org.apache.coyote.http11.InternalNioOutputBuffer$SocketOutputBuffer.doWrite(InternalNioOutputBuffer.java:321)
at
org.apache.coyote.http11.filters.ChunkedOutputFilter.doWrite(ChunkedOutputFilter.java:116)
at
org.apache.coyote.http11.AbstractOutputBuffer.doWrite(AbstractOutputBuffer.java:257)
at org.apache.coyote.Response.doWrite(Response.java:520)
at
org.apache.catalina.connector.OutputBuffer.realWriteBytes(OutputBuffer.java:391)
... 16 more
2.) 19-Dec-2013 11:14:34.470 SEVERE [http-nio-8080-ClientPoller-0]
org.apache.tomcat.util.net.NioEndpoint$PollerEvent.run
java.nio.channels.ClosedChannelException
at
java.nio.channels.spi.AbstractSelectableChannel.register(AbstractSelectableChannel.java:194)
at
org.apache.tomcat.util.net.NioEndpoint$PollerEvent.run(NioEndpoint.java:797)
at
org.apache.tomcat.util.net.NioEndpoint$Poller.events(NioEndpoint.java:925)
at
org.apache.tomcat.util.net.NioEndpoint$Poller.run(NioEndpoint.java:1045)
at java.lang.Thread.run(Thread.java:744)
I put together a unit test that replicates the async context timeout issue.
Code is listed below. When run, you'll see that it processes some of the
requests but fails due to a timeout. I've not been able to replicate the other
exceptions with the unit test though, so those may be unrelated.
public class TestWriteListener extends TomcatBaseTest {
private static final int BLOCK_SIZE = 8192;
private static final byte[] DATA = new byte[BLOCK_SIZE];
@Test
public void testEchoListener1() throws Exception {
Tomcat tomcat = getTomcatInstance();
// Must have a real docBase - just use temp
StandardContext ctx = (StandardContext) tomcat.addContext(,
Re: Non-Blocking IO Write Issue
On 20 December 2013 04:10, Daniel Mikusa dmik...@gopivotal.com wrote:
When run, you'll see that it processes some of the requests but fails due to
a timeout. I've not been able to replicate the other exceptions with the
unit test though, so those may be unrelated.
@WebServlet(asyncSupported = true)
public class DataStreamingServlet extends HttpServlet {
@Override
protected void service(HttpServletRequest request,
HttpServletResponse response) throws ServletException, IOException
{
...
DataStreamWriteListener dswl = new
DataStreamWriteListener(asyncContext, blocks);
response.getOutputStream().setWriteListener(dswl);
}
private class DataStreamWriteListener implements WriteListener {
@Override
public void onWritePossible() throws IOException {
ServletOutputStream output =
context.getResponse().getOutputStream();
Any thoughts on what's happening here?
This is a total guess ... getOutputStream() is waiting on a lock it
will never acquire? (Increase the timeout, do a thread-dump). What
happens if you instead pass the ServletOutputStream to the
DataStreamWriteListener's constructor?
cheers,
David.
-
To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org
For additional commands, e-mail: users-h...@tomcat.apache.org
