Re: long running socketwrite

Wed, 30 Mar 2016 15:17:45 -0700 


On 3/30/16 10:25 AM, Rallavagu wrote:



On 3/30/16 9:55 AM, Christopher Schultz wrote:

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

Rallavagu,

On 3/30/16 11:54 AM, Rallavagu wrote:

Tomcat 7.0.47, JDK 7

I have following long running socketwrite thread (more than 10
sec). Wondering what could cause this so I can further look and
investigate.

"http-bio-28080-exec-1497" daemon prio=10 tid=0x00007f812c230800
nid=0x72fa runnable [0x00007f80010f9000] java.lang.Thread.State:
RUNNABLE at java.net.SocketOutputStream.socketWrite0(Native
Method) at
java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:113)



at java.net.SocketOutputStream.write(SocketOutputStream.java:159)

at
org.apache.coyote.http11.InternalOutputBuffer.realWriteBytes(InternalO

utputBuffer.java:215)


  at
org.apache.tomcat.util.buf.ByteChunk.flushBuffer(ByteChunk.java:480)



at

org.apache.coyote.http11.InternalOutputBuffer.flush(InternalOutputBuff

er.java:119)


  at
org.apache.coyote.http11.AbstractHttp11Processor.action(AbstractHttp11

Processor.java:805)


  at org.apache.coyote.Response.action(Response.java:174) at
org.apache.catalina.connector.OutputBuffer.doFlush(OutputBuffer.java:3

66)




at

org.apache.catalina.connector.OutputBuffer.flush(OutputBuffer.java:333

)




at

org.apache.catalina.connector.CoyoteOutputStream.flush(CoyoteOutputStr

eam.java:101)


  at
org.springframework.security.web.context.SaveContextOnUpdateOrErrorRes

ponseWrapper$SaveContextServletOutputStream.flush(SaveContextOnUpdateOrE
rrorResponseWrapper.java:354)


  at
com.sun.jersey.spi.container.servlet.WebComponent$Writer.flush(WebComp

onent.java:308)


  at
com.sun.jersey.spi.container.ContainerResponse$CommittingOutputStream.

flush(ContainerResponse.java:146)


  at sun.nio.cs.StreamEncoder.implFlush(StreamEncoder.java:297) at
sun.nio.cs.StreamEncoder.flush(StreamEncoder.java:141) - locked
<0x000000075a610750> (a java.io.OutputStreamWriter) at
java.io.OutputStreamWriter.flush(OutputStreamWriter.java:229) at
java.io.BufferedWriter.flush(BufferedWriter.java:254) - locked
<0x000000075a610750> (a java.io.OutputStreamWriter) at
com.sun.jersey.core.util.ReaderWriter.writeToAsString(ReaderWriter.jav

a:191)


  at
com.sun.jersey.core.provider.AbstractMessageReaderWriterProvider.write

ToAsString(AbstractMessageReaderWriterProvider.java:128)


  at
com.sun.jersey.core.impl.provider.entity.StringProvider.writeTo(String

Provider.java:88)


  at
com.sun.jersey.core.impl.provider.entity.StringProvider.writeTo(String

Provider.java:58)


  at
com.sun.jersey.spi.container.ContainerResponse.write(ContainerResponse

.java:302)


  at
com.sun.jersey.server.impl.application.WebApplicationImpl._handleReque

st(WebApplicationImpl.java:1510)


  at
com.sun.jersey.server.impl.application.WebApplicationImpl.handleReques

t(WebApplicationImpl.java:1419)


  at
com.sun.jersey.server.impl.application.WebApplicationImpl.handleReques

t(WebApplicationImpl.java:1409)


  at
com.sun.jersey.spi.container.servlet.WebComponent.service(WebComponent

.java:409)


  at
com.sun.jersey.spi.container.servlet.ServletContainer.service(ServletC

ontainer.java:558)


  at
com.sun.jersey.spi.container.servlet.ServletContainer.service(ServletC

ontainer.java:733)


  at javax.servlet.http.HttpServlet.service(HttpServlet.java:728)


This is during slow response times where many threads were opened
(Tomcat configured with 500). Also, thread dump shows that 240 of
tomcat threads are in following state which suggests that they are
idle.

"http-bio-28080-exec-1230" daemon prio=10 tid=0x00007f812c361800
nid=0x29a0 waiting on condition [0x00007f810a7e6000]
java.lang.Thread.State: TIMED_WAITING (parking) at
sun.misc.Unsafe.park(Native Method) - parking to wait for
<0x000000071d193f50> (a
java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)



at

java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:226)



at

java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.

awaitNanos(AbstractQueuedSynchronizer.java:2082)


  at
java.util.concurrent.LinkedBlockingQueue.poll(LinkedBlockingQueue.java

:467)




at org.apache.tomcat.util.threads.TaskQueue.poll(TaskQueue.java:86)

at
org.apache.tomcat.util.threads.TaskQueue.poll(TaskQueue.java:32)
at
java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.jav

a:1068)


  at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.j

ava:1130)


  at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.

java:615)


  at java.lang.Thread.run(Thread.java:744)

Any clues would help. Thanks.


So ~50% of your request-processing threads are active, and at least
one of them is hanging on socket.write().

I would imagine you have a slow or unreliable client (e.g. mobile
phone with a bad connection) or the client has disappeared but the
socket hasn't closed, yet.

You can set a write timeouts on your sockets, but you might end up
with more server-side errors and cranky clients getting connections
dropped.


Thanks for the clue. Actually, there are multiple (185) of these long
running socketwrite threads that are running for more than 10 seconds.




After further investigation, here is the snippet from stacktrace that 
instrumentation APM found where there is a ClientAbortException thrown.


org.apache.catalina.connector.ClientAbortException.null

      at 
org.apache.catalina.connector.OutputBuffer.doFlush(OutputBuffer.java:371)
      at 
org.apache.catalina.connector.OutputBuffer.flush(OutputBuffer.java:333)
      at 
org.apache.catalina.connector.CoyoteOutputStream.flush(CoyoteOutputStream.java:101)
      at 
org.springframework.security.web.context.SaveContextOnUpdateOrErrorResponseWrapper$SaveContextServletOutputStream.flush(SaveContextOnUpdateOrErrorResponseWrapper.java:354)
      at 
com.sun.jersey.spi.container.servlet.WebComponent$Writer.flush(WebComponent.java:308)
      at 
com.sun.jersey.spi.container.ContainerResponse$CommittingOutputStream.flush(ContainerResponse.java:146)

      at sun.nio.cs.StreamEncoder.implFlush(StreamEncoder.java:297)
      at sun.nio.cs.StreamEncoder.flush(StreamEncoder.java:141)
      at java.io.OutputStreamWriter.flush(OutputStreamWriter.java:229)
      at java.io.BufferedWriter.flush(BufferedWriter.java:254)

      at 
com.sun.jersey.core.util.ReaderWriter.writeToAsString(ReaderWriter.java:191)
      at 
com.sun.jersey.core.provider.AbstractMessageReaderWriterProvider.writeToAsString(AbstractMessageReaderWriterProvider.java:128)
      at 
com.sun.jersey.core.impl.provider.entity.StringProvider.writeTo(StringProvider.java:88)
      at 
com.sun.jersey.core.impl.provider.entity.StringProvider.writeTo(StringProvider.java:58)
      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:558)
      at 
com.sun.jersey.spi.container.servlet.ServletContainer.service(ServletContainer.java:733)

      at javax.servlet.http.HttpServlet.service(HttpServlet.java:728)



However, the thread continue to live in "RUNNABLE" state as below. I 
wonder what makes the thread not to disconnect.


java.lang.Thread.State: RUNNABLE
        at java.net.SocketOutputStream.socketWrite0(Native Method)

        at 
java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:113)

        at java.net.SocketOutputStream.write(SocketOutputStream.java:159)

        at 
org.apache.coyote.http11.InternalOutputBuffer.realWriteBytes(InternalOutputBuffer.java:215)
        at 
org.apache.tomcat.util.buf.ByteChunk.flushBuffer(ByteChunk.java:480)
        at 
org.apache.coyote.http11.InternalOutputBuffer.flush(InternalOutputBuffer.java:119)
        at 
org.apache.coyote.http11.AbstractHttp11Processor.action(AbstractHttp11Processor.java:805)

        at org.apache.coyote.Response.action(Response.java:174)

        at 
org.apache.catalina.connector.OutputBuffer.doFlush(OutputBuffer.java:366)
        at 
org.apache.catalina.connector.OutputBuffer.flush(OutputBuffer.java:333)
        at 
org.apache.catalina.connector.CoyoteOutputStream.flush(CoyoteOutputStream.java:101)
        at 
org.springframework.security.web.context.SaveContextOnUpdateOrErrorResponseWrapper$SaveContextServletOutputStream.flush(SaveContextOnUpdateOrErrorResponseWrapper.java:354)
        at 
com.sun.jersey.spi.container.servlet.WebComponent$Writer.flush(WebComponent.java:308)
        at 
com.sun.jersey.spi.container.ContainerResponse$CommittingOutputStream.flush(ContainerResponse.java:146)

        at sun.nio.cs.StreamEncoder.implFlush(StreamEncoder.java:297)
        at sun.nio.cs.StreamEncoder.flush(StreamEncoder.java:141)
        - locked <0x000000075644bc58> (a java.io.OutputStreamWriter)
        at java.io.OutputStreamWriter.flush(OutputStreamWriter.java:229)
        at java.io.BufferedWriter.flush(BufferedWriter.java:254)
        - locked <0x000000075644bc58> (a java.io.OutputStreamWriter)

        at 
com.sun.jersey.core.util.ReaderWriter.writeToAsString(ReaderWriter.java:191)
        at 
com.sun.jersey.core.provider.AbstractMessageReaderWriterProvider.writeToAsString(AbstractMessageReaderWriterProvider.java:128)
        at 
com.sun.jersey.core.impl.provider.entity.StringProvider.writeTo(StringProvider.java:88)
        at 
com.sun.jersey.core.impl.provider.entity.StringProvider.writeTo(StringProvider.java:58)
        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:558)
        at 
com.sun.jersey.spi.container.servlet.ServletContainer.service(ServletContainer.java:733)

        at javax.servlet.http.HttpServlet.service(HttpServlet.java:728)





- -chris
-----BEGIN PGP SIGNATURE-----
Comment: GPGTools - http://gpgtools.org
Comment: Using GnuPG with Thunderbird - http://www.enigmail.net/

iEYEARECAAYFAlb8BRkACgkQ9CaO5/Lv0PCu9QCfZejhctedau7gZzPbhOpllIH7
7ooAnjwHoWz3/aLkjKKDSFlUs3n47MMN
=cJ/8
-----END PGP SIGNATURE-----

---------------------------------------------------------------------
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























					Reply via email to