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