I have a dropwizard 0.7.0 service.
- jetty 9.0.7
- jersey 1.18.1
Occasionally (1 in 5000 requets) the service will spend 60 seconds writing it's response. AppDynamics is showing that 60 seconds are being spent inside com.sun.jersey.spi.container.servlet.WebComponent$Writer:write:300. After 60 seconds we get the following exception:
org.eclipse.jetty.io.EofException.Closed at org.eclipse.jetty.server.HttpOutput.write(HttpOutput.java:171) at org.eclipse.jetty.servlets.gzip.AbstractCompressedStream.write(AbstractCompressedStream.java:226) at com.sun.jersey.spi.container.servlet.WebComponent$Writer.write(WebComponent.java:300) at com.sun.jersey.spi.container.ContainerResponse$CommittingOutputStream.write(ContainerResponse.java:135) at com.fasterxml.jackson.core.json.UTF8JsonGenerator._flushBuffer(UTF8JsonGenerator.java:1862) at com.fasterxml.jackson.core.json.UTF8JsonGenerator.close(UTF8JsonGenerator.java:1087) at com.fasterxml.jackson.jaxrs.base.ProviderBase.writeTo(ProviderBase.java:649) at com.sun.jersey.spi.container.ContainerResponse.write(ContainerResponse.java:302) at com.sun.jersey.server.impl.application.WebApplicationImpl._handleRequest(WebApplicationImpl.java:1510) at com.sun.jersey.server.impl.application.WebApplicationImpl.handleRequest(WebApplicationImpl.java:1419) at com.sun.jersey.server.impl.application.WebApplicationImpl.handleRequest(WebApplicationImpl.java:1409) at com.sun.jersey.spi.container.servlet.WebComponent.service(WebComponent.java:409) at com.sun.jersey.spi.container.servlet.ServletContainer.service(ServletContainer.java:540) at com.sun.jersey.spi.container.servlet.ServletContainer.service(ServletContainer.java:715) at javax.servlet.http.HttpServlet.service(HttpServlet.java:848) at io.dropwizard.jetty.NonblockingServletHolder.handle(NonblockingServletHolder.java:49) at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1515) at org.eclipse.jetty.servlets.UserAgentFilter.doFilter(UserAgentFilter.java:83) at org.eclipse.jetty.servlets.GzipFilter.doFilter(GzipFilter.java:348) at io.dropwizard.jetty.BiDiGzipFilter.doFilter(BiDiGzipFilter.java:127) at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1486) at io.dropwizard.servlets.ThreadNameFilter.doFilter(ThreadNameFilter.java:29) at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1486) at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:519) at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1097) at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:448) at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1031) at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:136) at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:97) at com.codahale.metrics.jetty9.InstrumentedHandler.handle(InstrumentedHandler.java:173) at io.dropwizard.jetty.RoutingHandler.handle(RoutingHandler.java:51) at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:97) at org.eclipse.jetty.server.handler.RequestLogHandler.handle(RequestLogHandler.java:92) at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:97) at org.eclipse.jetty.server.handler.StatisticsHandler.handle(StatisticsHandler.java:162) at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:97) at org.eclipse.jetty.server.Server.handle(Server.java:446) at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:271) at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:246) at org.eclipse.jetty.io.AbstractConnection$ReadCallback.run(AbstractConnection.java:358) at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:601) at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:532) at java.lang.Thread.run(Thread.java:744)
We also see the following in the logs that shows that the connection is idle for at least 30 seconds:
WARN [2015-05-14 09:54:30,511] org.eclipse.jetty.server.HttpChannel: commit failed ! java.util.concurrent.TimeoutException: Idle timeout expired: 30001/30000 ms ! at org.eclipse.jetty.io.IdleTimeout.checkIdleTimeout(IdleTimeout.java:153) ~[report-configuration-service-1.0.6.2.0.jar:na] ! at org.eclipse.jetty.io.IdleTimeout$1.run(IdleTimeout.java:50) ~[report-configuration-service-1.0.6.2.0.jar:na] ! at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471) ~[na:1.7.0_45] ! at java.util.concurrent.FutureTask.run(FutureTask.java:262) ~[na:1.7.0_45] ! at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:178) ~[na:1.7.0_45] ! at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:292) ~[na:1.7.0_45] ! at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) ~[na:1.7.0_45] ! at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) ~[na:1.7.0_45] ! at java.lang.Thread.run(Thread.java:744) [na:1.7.0_45]
What could cause such behaviour?
A couple of other observations:
- The errors do not correspond with peaks in load.
- This error happens on multiple endpoints; there is no definite link between these endpoints, but they are some of the endpoints returning larger entities.
- The resource method is succeeding, i.e. the entity is fetched from the database successfully along with any required processing and authorization.