You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@tomcat.apache.org by bu...@apache.org on 2013/06/26 08:39:56 UTC

[Bug 55144] New: NIO connection locked when trying to release it

https://issues.apache.org/bugzilla/show_bug.cgi?id=55144

            Bug ID: 55144
           Summary: NIO connection locked when trying to release it
           Product: Tomcat 7
           Version: 7.0.41
          Hardware: PC
            Status: NEW
          Severity: major
          Priority: P2
         Component: Connectors
          Assignee: dev@tomcat.apache.org
          Reporter: pavel.rekun@gmail.com

I'm using Atmoshphere framework and when I try to resume a resource it locks
(can be for hours)

I'm not sure how to reproduce since it's happening on our prod servers.
Using 
windows server 2008 standard x64 R2, 
tomcat 7.0.41, 
java jrockit-jdk1.6.0_37-R28.2.5-4.1.0

This was happening since version 7.0.30 (that's the one we started using)

see dump:
"CleanResourceTask" id=79 idx=0x14c tid=228160 prio=5 alive, parked,
native_blocked, daemon
    at jrockit/vm/Locks.park0(J)V(Native Method)
    at jrockit/vm/Locks.park(Locks.java:2230)[optimized]
    at jrockit/proxy/sun/misc/Unsafe.park(Unsafe.java:616)[inlined]
    at
java/util/concurrent/locks/LockSupport.parkNanos(LockSupport.java:196)[inlined]
    at
java/util/concurrent/locks/AbstractQueuedSynchronizer.doAcquireSharedNanos(AbstractQueuedSynchronizer.java:1011)[inlined]
    at
java/util/concurrent/locks/AbstractQueuedSynchronizer.tryAcquireSharedNanos(AbstractQueuedSynchronizer.java:1303)[inlined]
    at
java/util/concurrent/CountDownLatch.await(CountDownLatch.java:253)[inlined]
    at
org/apache/tomcat/util/net/NioEndpoint$KeyAttachment.awaitLatch(NioEndpoint.java:1577)[inlined]
    at
org/apache/tomcat/util/net/NioEndpoint$KeyAttachment.awaitWriteLatch(NioEndpoint.java:1580)[inlined]
    at
org/apache/tomcat/util/net/NioBlockingSelector.write(NioBlockingSelector.java:109)[optimized]
    at
org/apache/tomcat/util/net/NioSelectorPool.write(NioSelectorPool.java:174)[optimized]
    at
org/apache/coyote/http11/InternalNioOutputBuffer.writeToSocket(InternalNioOutputBuffer.java:163)[inlined]
    at
org/apache/coyote/http11/InternalNioOutputBuffer.flushBuffer(InternalNioOutputBuffer.java:242)[optimized]
    ^-- Holding lock:
org/apache/coyote/http11/InternalNioOutputBuffer@0x0000000222F4BE70[fat lock]
    at
org/apache/coyote/http11/InternalNioOutputBuffer.endRequest(InternalNioOutputBuffer.java:121)
    at
org/apache/coyote/http11/AbstractHttp11Processor.action(AbstractHttp11Processor.java:752)[optimized]
    at org/apache/coyote/Response.action(Response.java:173)[inlined]
    at org/apache/coyote/Response.finish(Response.java:279)[inlined]
    at
org/apache/catalina/connector/OutputBuffer.close(OutputBuffer.java:313)[optimized]
    at org/apache/catalina/connector/Response.finishResponse(Response.java:512)
    at
org/apache/catalina/connector/CometEventImpl.close(CometEventImpl.java:96)
    at
org/atmosphere/container/Tomcat7CometSupport.bz51881(Tomcat7CometSupport.java:178)[optimized]
    at
org/atmosphere/container/Tomcat7CometSupport.action(Tomcat7CometSupport.java:209)
    at
org/atmosphere/container/Tomcat7CometSupport.action(Tomcat7CometSupport.java:47)
    at
org/atmosphere/cpr/AtmosphereResourceImpl.resume(AtmosphereResourceImpl.java:323)[optimized]
    at
com/fx/tasks/CleanResourceTask.resumeOldResources(CleanResourceTask.java:97)[inlined]
    at
com/fx/tasks/CleanResourceTask.access$200(CleanResourceTask.java:26)[optimized]
    at com/fx/tasks/CleanResourceTask$1.run(CleanResourceTask.java:51)
    at java/lang/Thread.run(Thread.java:662)
    at jrockit/vm/RNI.c2java(JJJJJ)V(Native Method)
    -- end of trace

-- 
You are receiving this mail because:
You are the assignee for the bug.

---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org


[Bug 55144] NIO connection locked when trying to release it

Posted by bu...@apache.org.
https://issues.apache.org/bugzilla/show_bug.cgi?id=55144

--- Comment #11 from Pavel <pa...@gmail.com> ---
I've discovered a strange behavior - even though I set a timeout of 20 sec on
the connector (in server.xml), sometimes it gets here:

att.awaitWriteLatch(writeTimeout,TimeUnit.MILLISECONDS);

With the timeout I've set for the suspend resource (resource.suspend(30
minutes))
and sometime with the 20 sec timeouts.

You can see my discussion here with the Jean (the creator of Atmosphere) and he
says that atmosphere doesn't have access to that API)

https://github.com/Atmosphere/atmosphere/issues/1148

Is this a tomcat bug?

-- 
You are receiving this mail because:
You are the assignee for the bug.

---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org


[Bug 55144] NIO connection locked when trying to release it

Posted by bu...@apache.org.
https://issues.apache.org/bugzilla/show_bug.cgi?id=55144

--- Comment #3 from Mark Thomas <ma...@apache.org> ---
Any way you can debug the instance to see that the timeout has been set to?

I'll have another look at the code and see if I can spot any possible code
paths that could lead to a much longer delay.

Is it possible that Atmosphere is changing the timeout?

Is it possible that the associated client has gone away?

-- 
You are receiving this mail because:
You are the assignee for the bug.

---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org


[Bug 55144] NIO connection locked when trying to release it

Posted by bu...@apache.org.
https://issues.apache.org/bugzilla/show_bug.cgi?id=55144

--- Comment #13 from Volker Kleinschmidt <vk...@blackboard.com> ---
Well, this actually WAS a valid bug - it got re-filed and fixed as
https://issues.apache.org/bugzilla/show_bug.cgi?id=55267
I'm just wondering why they're not linked together.

-- 
You are receiving this mail because:
You are the assignee for the bug.

---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org


[Bug 55144] NIO connection locked when trying to release it

Posted by bu...@apache.org.
https://issues.apache.org/bugzilla/show_bug.cgi?id=55144

--- Comment #12 from Mark Thomas <ma...@apache.org> ---
Something is setting the timeout to 30 minutes and that something isn't Tomcat. 

If Tomcat was using the wrong / old timeout then that would be a Tomcat bug but
I don't see any evidence of that here.

-- 
You are receiving this mail because:
You are the assignee for the bug.

---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org


[Bug 55144] NIO connection locked when trying to release it

Posted by bu...@apache.org.
https://issues.apache.org/bugzilla/show_bug.cgi?id=55144

--- Comment #5 from Mark Thomas <ma...@apache.org> ---
It is good to know that Atmosphere doesn't appear to change the timeout but the
question I asked was for one of these blocked threads can you see what the
timeout has actually been set to? If the timeout is huge, we need to find out
where it is set. If the timeout is normal and the thread blocks for longer than
the timeout then that points to a JVM bug.

-- 
You are receiving this mail because:
You are the assignee for the bug.

---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org


[Bug 55144] NIO connection locked when trying to release it

Posted by bu...@apache.org.
https://issues.apache.org/bugzilla/show_bug.cgi?id=55144

Mark Thomas <ma...@apache.org> changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
             Status|NEW                         |NEEDINFO
                 OS|                            |All

--- Comment #1 from Mark Thomas <ma...@apache.org> ---
I'm leaning towards resolving this as invalid. Tomcat is waiting to write some
data and is waiting for the configured timeout (not sure if Atmosphere or the
app sets the timeout) to send the data. If Tomcat is waiting for hours that is
because of the timeout that has been configured.

I don't see any evidence in this report of incorrect behaviour by Tomcat.

-- 
You are receiving this mail because:
You are the assignee for the bug.

---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org


[Bug 55144] NIO connection locked when trying to release it

Posted by bu...@apache.org.
https://issues.apache.org/bugzilla/show_bug.cgi?id=55144

--- Comment #7 from Pavel <pa...@gmail.com> ---
See this new dump - I'm also seeing gzip in the stacktrace - maybe it's
contributing to the problem.

"CleanResourceTask" id=81 idx=0x154 tid=220556 prio=5 alive, interrupted,
blocked, native_blocked, daemon
    -- Blocked trying to get lock:
org/apache/coyote/http11/InternalNioOutputBuffer@0x00000001D9CAC6E8[thin lock]
    at jrockit/vm/Threads.sleep(I)V(Native Method)
    at jrockit/vm/Locks.waitForThinRelease(Locks.java:955)[optimized]
    at jrockit/vm/Locks.monitorEnterSecondStageHard(Locks.java:1083)[optimized]
    at jrockit/vm/Locks.monitorEnterSecondStage(Locks.java:1005)[optimized]
    at
org/apache/coyote/http11/InternalNioOutputBuffer.addToBB(InternalNioOutputBuffer.java:208)[inlined]
    at
org/apache/coyote/http11/InternalNioOutputBuffer.access$000(InternalNioOutputBuffer.java:41)[inlined]
    at
org/apache/coyote/http11/InternalNioOutputBuffer$SocketOutputBuffer.doWrite(InternalNioOutputBuffer.java:268)[optimized]
    at
org/apache/coyote/http11/filters/ChunkedOutputFilter.doWrite(ChunkedOutputFilter.java:117)[optimized]
    at
org/apache/coyote/http11/filters/GzipOutputFilter$FakeOutputStream.write(GzipOutputFilter.java:177)[optimized]
    at java/util/zip/GZIPOutputStream.finish(GZIPOutputStream.java:91)
    at
org/apache/coyote/http11/filters/FlushableGZIPOutputStream.finish(FlushableGZIPOutputStream.java:84)
    ^-- Holding lock:
org/apache/coyote/http11/filters/FlushableGZIPOutputStream@0x00000001D9CF1698[thin
lock]
    at
org/apache/coyote/http11/filters/GzipOutputFilter.end(GzipOutputFilter.java:141)
    at
org/apache/coyote/http11/AbstractOutputBuffer.endRequest(AbstractOutputBuffer.java:310)
    at
org/apache/coyote/http11/InternalNioOutputBuffer.endRequest(InternalNioOutputBuffer.java:120)
    at
org/apache/coyote/http11/AbstractHttp11Processor.action(AbstractHttp11Processor.java:752)[optimized]
    at org/apache/coyote/Response.action(Response.java:173)[inlined]
    at org/apache/coyote/Response.finish(Response.java:279)[inlined]
    at
org/apache/catalina/connector/OutputBuffer.close(OutputBuffer.java:313)[optimized]
    at org/apache/catalina/connector/Response.finishResponse(Response.java:512)
    at
org/apache/catalina/connector/CometEventImpl.close(CometEventImpl.java:96)
    at
org/atmosphere/container/Tomcat7CometSupport.bz51881(Tomcat7CometSupport.java:178)[optimized]
    at
org/atmosphere/container/Tomcat7CometSupport.action(Tomcat7CometSupport.java:209)
    at
org/atmosphere/container/Tomcat7CometSupport.action(Tomcat7CometSupport.java:47)
    at
org/atmosphere/cpr/AtmosphereResourceImpl.resume(AtmosphereResourceImpl.java:323)[optimized]
    at
com/fx/tasks/CleanResourceTask.resumeOldResources(CleanResourceTask.java:124)[optimized]
    at com/fx/tasks/CleanResourceTask.access$400(CleanResourceTask.java:26)
    at com/fx/tasks/CleanResourceTask$2.run(CleanResourceTask.java:78)
    at java/lang/Thread.run(Thread.java:662)
    at jrockit/vm/RNI.c2java(JJJJJ)V(Native Method)
    -- end of trace

"Atmosphere-Shared-AsyncOp-593" id=1499 idx=0x1738 tid=209140 prio=5 alive,
parked, native_blocked, daemon
    at jrockit/vm/Locks.park0(J)V(Native Method)
    at jrockit/vm/Locks.park(Locks.java:2230)[optimized]
    at jrockit/proxy/sun/misc/Unsafe.park(Unsafe.java:616)[inlined]
    at
java/util/concurrent/locks/LockSupport.parkNanos(LockSupport.java:196)[inlined]
    at
java/util/concurrent/locks/AbstractQueuedSynchronizer.doAcquireSharedNanos(AbstractQueuedSynchronizer.java:1011)[inlined]
    at
java/util/concurrent/locks/AbstractQueuedSynchronizer.tryAcquireSharedNanos(AbstractQueuedSynchronizer.java:1303)[inlined]
    at
java/util/concurrent/CountDownLatch.await(CountDownLatch.java:253)[inlined]
    at
org/apache/tomcat/util/net/NioEndpoint$KeyAttachment.awaitLatch(NioEndpoint.java:1577)[inlined]
    at
org/apache/tomcat/util/net/NioEndpoint$KeyAttachment.awaitWriteLatch(NioEndpoint.java:1580)[inlined]
    at
org/apache/tomcat/util/net/NioBlockingSelector.write(NioBlockingSelector.java:109)[optimized]
    at
org/apache/tomcat/util/net/NioSelectorPool.write(NioSelectorPool.java:174)[optimized]
    at
org/apache/coyote/http11/InternalNioOutputBuffer.writeToSocket(InternalNioOutputBuffer.java:163)[inlined]
    at
org/apache/coyote/http11/InternalNioOutputBuffer.flushBuffer(InternalNioOutputBuffer.java:242)[inlined]
    at
org/apache/coyote/http11/InternalNioOutputBuffer.flush(InternalNioOutputBuffer.java:94)[optimized]
    ^-- Holding lock:
org/apache/coyote/http11/InternalNioOutputBuffer@0x00000001D9CAC6E8[thin lock]
    at
org/apache/coyote/http11/AbstractHttp11Processor.action(AbstractHttp11Processor.java:793)[optimized]
    at org/apache/coyote/Response.action(Response.java:173)[inlined]
    at
org/apache/catalina/connector/OutputBuffer.doFlush(OutputBuffer.java:359)[inlined]
    at
org/apache/catalina/connector/OutputBuffer.flush(OutputBuffer.java:326)[inlined]
    at
org/apache/catalina/connector/CoyoteOutputStream.flush(CoyoteOutputStream.java:101)[optimized]
    at
org/atmosphere/handler/AbstractReflectorAtmosphereHandler.onStateChange(AbstractReflectorAtmosphereHandler.java:134)[optimized]
    at
org/atmosphere/cpr/DefaultBroadcaster.invokeOnStateChange(DefaultBroadcaster.java:1093)[inlined]
    at
org/atmosphere/cpr/DefaultBroadcaster.prepareInvokeOnStateChange(DefaultBroadcaster.java:1113)[optimized]
    at
org/atmosphere/cpr/DefaultBroadcaster.executeAsyncWrite(DefaultBroadcaster.java:998)[optimized]
    at
org/atmosphere/cpr/DefaultBroadcaster$3.run(DefaultBroadcaster.java:619)[optimized]
    ^-- Holding lock:
org/atmosphere/cpr/AtmosphereResourceImpl@0x00000001D9CA8AA0[thin lock]
    at
java/util/concurrent/Executors$RunnableAdapter.call(Executors.java:439)[optimized]
    at
java/util/concurrent/FutureTask$Sync.innerRun(FutureTask.java:303)[inlined]
    at java/util/concurrent/FutureTask.run(FutureTask.java:138)[optimized]
    at
java/util/concurrent/ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:895)[optimized]
    at
java/util/concurrent/ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:918)
    at java/lang/Thread.run(Thread.java:662)[optimized]
    at jrockit/vm/RNI.c2java(JJJJJ)V(Native Method)
    -- end of trace

-- 
You are receiving this mail because:
You are the assignee for the bug.

---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org


[Bug 55144] NIO connection locked when trying to release it

Posted by bu...@apache.org.
https://issues.apache.org/bugzilla/show_bug.cgi?id=55144

Mark Thomas <ma...@apache.org> changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
             Status|NEEDINFO                    |RESOLVED
         Resolution|---                         |INVALID

--- Comment #10 from Mark Thomas <ma...@apache.org> ---
Next question - are those threads blocking for more than 30 minutes after the
write attempt? If yes, that is points to a JVM bug. If not, then everything is
working as designed.

Given the above, I don't see a Tomcat bug here so I am resolving this as
INVALID. Feel free to continue this discussion on the users list. If your
investigation does discover a bug (e.g. Tomcat fails to act on a something
(e.g. an exception) that should result in the socket being closed) then feel
free to re-open this issue.

I'd suggest that the CleanResourceTask sets the timeout a lot lower (e.g. 20s)
before trying to write to the socket. While 30mins is OK for a read timeout it
is way too high for a blocking write.

-- 
You are receiving this mail because:
You are the assignee for the bug.

---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org


[Bug 55144] NIO connection locked when trying to release it

Posted by bu...@apache.org.
https://issues.apache.org/bugzilla/show_bug.cgi?id=55144

--- Comment #9 from Pavel <pa...@gmail.com> ---
I did a heap dump - and discovered 2 things:

1. timeout is normal (setting to 30 minutes in atmosphere and it's the same in
the locked thread)

2. the nio connection is an HTTPS

I haven't tested https in my local tests - I'll test it and see if I can
reproduce.

Any idea why https would cause an issue?

-- 
You are receiving this mail because:
You are the assignee for the bug.

---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org


[Bug 55144] NIO connection locked when trying to release it

Posted by bu...@apache.org.
https://issues.apache.org/bugzilla/show_bug.cgi?id=55144

--- Comment #6 from Pavel <pa...@gmail.com> ---
Missed that question :)

I'm not sure how can I check the timeout for one of the locked threads... (I
can't reproduce it locally)

I did check the timeout for atmosphere threads and it looks normal (uses the
timeout I've set in tomcat conf)

Do you have a temp workaround in the meanwhile ? It causes tomcat to crash
(keeps opening more and more threads)

-- 
You are receiving this mail because:
You are the assignee for the bug.

---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org


[Bug 55144] NIO connection locked when trying to release it

Posted by bu...@apache.org.
https://issues.apache.org/bugzilla/show_bug.cgi?id=55144

--- Comment #8 from Mark Thomas <ma...@apache.org> ---
If you can take a thread dump then you should be able to take a heap dump as
well. You can then load the heap dump into a profiler and take a look at the
current value of the timeout. Knowing the timeout value is key to figuring out
where to go next with this.

-- 
You are receiving this mail because:
You are the assignee for the bug.

---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org


[Bug 55144] NIO connection locked when trying to release it

Posted by bu...@apache.org.
https://issues.apache.org/bugzilla/show_bug.cgi?id=55144

--- Comment #4 from Pavel <pa...@gmail.com> ---
I debugged and I don't see that Atmosphere rewrites the timeout.

As to the client going away - how do I check this? That's what I was suspecting
at the beginning but I'm not sure how to reproduce. 

The whole point of the "CleanResourceTask"  is to release connections that are
active for more than 30 minutes, cause for some reason it wasn't able to detect
a disconnect event.

-- 
You are receiving this mail because:
You are the assignee for the bug.

---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org


[Bug 55144] NIO connection locked when trying to release it

Posted by bu...@apache.org.
https://issues.apache.org/bugzilla/show_bug.cgi?id=55144

--- Comment #2 from Pavel <pa...@gmail.com> ---
here is my connection config:

    <Connector address="1.1.1.1" connectionTimeout="20000" port="80"
protocol="org.apache.coyote.http11.Http11NioProtocol" redirectPort="8443"
    maxThreads="500"
    acceptCount="100"
    acceptorThreadCount="5"
    compression="on"
  compressionMinSize="0"
  noCompressionUserAgents="gozilla, traviata"
 
compressableMimeType="text/html,text/plain,text/xml,text/css,text/javascript,application/javascript,application/x-javascript,application/json"
    />

As you can see it has a timeout of 20 sec - so I'm not sure how it can lock for
hours.

-- 
You are receiving this mail because:
You are the assignee for the bug.

---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org