I have a dropwizard 0.7.0 service.
- jetty 9.0.7
- jersey 1.18.1
Occasionally (1 in 5000 requests) the service will spend 60 seconds writing its 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.