You are viewing a plain text version of this content. The canonical link for it is here.
Posted to user@cayenne.apache.org by Mike Kienenberger <mk...@gmail.com> on 2015/07/31 23:01:33 UTC

Re: java.sql.SQLException: Can't obtain connection. Request timed out.

]
So I'm reviewing a dump of the threads when I run out of connections
in my connection pool, and I think I've found the problem.

I don't understand what's going on.  While the oracle driver is
reading data, some kind of thread wrapper
[org.apache.tomcat.util.threads.TaskThread$WrappingRunnable] inside of
tomcat is triggered, and this re-executes the entire servlet stack
again.   It almost seems as if the oracle connection to the database
is hitting the tomcat server instead of the database.

This is not the only thread displaying this behaviour.   The entire
thread dump was 100,000 lines and this thread dump was only 4300 lines
long, so it's a mind-boggling amount of data to sift through.

Here's the start...

[...]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
    at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
    at java.lang.Thread.run(Thread.java:745)
[repeats at least 65 more times...]
[And here we start repeating again...^^^^....]
    at java.net.SocketInputStream.socketRead0(Native Method)
    at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
    at java.net.SocketInputStream.read(SocketInputStream.java:170)
    at java.net.SocketInputStream.read(SocketInputStream.java:141)
    at oracle.net.ns.Packet.receive(Packet.java:300)
    at oracle.net.ns.DataPacket.receive(DataPacket.java:106)
    at oracle.net.ns.NetInputStream.getNextPacket(NetInputStream.java:315)
    at oracle.net.ns.NetInputStream.read(NetInputStream.java:260)
    at oracle.net.ns.NetInputStream.read(NetInputStream.java:185)
    at oracle.net.ns.NetInputStream.read(NetInputStream.java:102)
    at oracle.jdbc.driver.T4CSocketInputStreamWrapper.readNextPacket(T4CSocketInputStreamWrapper.java:124)
    at oracle.jdbc.driver.T4CSocketInputStreamWrapper.read(T4CSocketInputStreamWrapper.java:80)
    at oracle.jdbc.driver.T4CMAREngine.unmarshalUB1(T4CMAREngine.java:1137)
    at oracle.jdbc.driver.T4CTTIfun.receive(T4CTTIfun.java:290)
    at oracle.jdbc.driver.T4CTTIfun.doRPC(T4CTTIfun.java:192)
    at oracle.jdbc.driver.T4C7Ocommoncall.doOCOMMIT(T4C7Ocommoncall.java:75)
    at oracle.jdbc.driver.T4CConnection.doCommit(T4CConnection.java:617)
    at oracle.jdbc.driver.PhysicalConnection.commit(PhysicalConnection.java:3901)
    at oracle.jdbc.driver.PhysicalConnection.commit(PhysicalConnection.java:3907)
    at org.apache.cayenne.conn.ConnectionWrapper.commit(ConnectionWrapper.java:136)
    at org.apache.cayenne.access.InternalTransaction.processCommit(InternalTransaction.java:73)
    at org.apache.cayenne.access.ExternalTransaction.commit(ExternalTransaction.java:97)
    at org.apache.cayenne.access.DataDomain.runInTransaction(DataDomain.java:878)
    at org.apache.cayenne.access.DataDomain.onSyncNoFilters(DataDomain.java:814)
    at org.apache.cayenne.access.DataDomain$DataDomainSyncFilterChain.onSync(DataDomain.java:1031)
    at org.apache.cayenne.access.DataDomain.onSync(DataDomain.java:785)
    at org.apache.cayenne.access.DataContext.flushToParent(DataContext.java:817)
    at org.apache.cayenne.access.DataContext.commitChanges(DataContext.java:756)
    at com.gvea.applications.epay.cayenne.BaseDAOCayenne.update(BaseDAOCayenne.java:338)
    at com.gvea.applications.epay.cayenne.EbppDAOCayenne.update(EbppDAOCayenne.java:84)
    at com.gvea.ebpp.business.CayennePageStateLogger.log(CayennePageStateLogger.java:42)
    at com.gvea.struts.ebpp.framework.Application.onDoRequest(Application.java:302)
    at com.gvea.servlet.pageStateCache.PageStateManager.onDoRequest(PageStateManager.java:648)
    at com.gvea.servlet.pageStateCache.PageStateCacheServlet.doRequest(PageStateCacheServlet.java:174)
    at com.gvea.servlet.pageStateCache.PageStateCacheServlet.doPost(PageStateCacheServlet.java:131)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:648)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:729)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:291)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
    at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:239)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
    at com.gvea.servlet.filter.LoggingFilter.doFilter(LoggingFilter.java:66)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:239)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
    at fr.xebia.servlet.filter.XForwardedFilter.doFilter(XForwardedFilter.java:899)
    at fr.xebia.servlet.filter.XForwardedFilter.doFilter(XForwardedFilter.java:915)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:239)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
    at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:219)
    at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:106)
    at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:502)
    at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:142)
    at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:79)
    at org.apache.catalina.valves.AbstractAccessLogValve.invoke(AbstractAccessLogValve.java:610)
    at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:88)
    at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:518)
    at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1091)
    at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:668)
    at org.apache.coyote.http11.Http11NioProtocol$Http11ConnectionHandler.process(Http11NioProtocol.java:223)
    at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1517)
    at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1474)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
    at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
    at java.lang.Thread.run(Thread.java:745)

[Start of the thread above]


On Fri, Jun 12, 2015 at 11:21 AM, Mike Kienenberger <mk...@gmail.com> wrote:
> Hmm.   I just remembered that I have a second infrequently-accessed
> database which is also configured.
>
> So I'd really have 3 runtimes * 2 connection pools, so that explains 6 of the 8.
>
> Not sure where the other two are from unless I have a 4th runtime that
> I've overlooked.
>
>
> On Cayenne 4, yes, that's one of my goals this summer -- upgrade to
> Cayenne 4.  Probably won't happen until July, though.
>
>
> I'm going to add something that will dump all threads when this
> exception is hit.
>
> On Fri, Jun 12, 2015 at 11:15 AM, Andrus Adamchik
> <an...@objectstyle.org> wrote:
>>
>>> On Jun 12, 2015, at 6:09 PM, Mike Kienenberger <mk...@gmail.com> wrote:
>>>
>>> And, interestingly enough, I only have 8 "PoolManagerCleanup" threads,
>>> and not the 9 that I expected.  Maybe they are create-on-demand and
>>> one of my runtimes hasn't needed it yet?
>>
>> There should be 3 actually. One per PoolManager, not one per connection. So something may be going on there.
>>
>> FWIW 4.0.M3 (master branch) has a completely new non-blocking alternative to PoolManager. The cleanup process is also more sane there.
>>
>> Andrus
>>

Re: java.sql.SQLException: Can't obtain connection. Request timed out.

Posted by Mike Kienenberger <mk...@gmail.com>.
Oops.  Stupid user error.   My thread dumper method was dumping each
thread trace as many times as there were lines in the thread trace.
So a 65-line trace created 65 copies...   What a mess I've made.

On Fri, Jul 31, 2015 at 5:01 PM, Mike Kienenberger <mk...@gmail.com> wrote:
> ]
> So I'm reviewing a dump of the threads when I run out of connections
> in my connection pool, and I think I've found the problem.
>
> I don't understand what's going on.  While the oracle driver is
> reading data, some kind of thread wrapper
> [org.apache.tomcat.util.threads.TaskThread$WrappingRunnable] inside of
> tomcat is triggered, and this re-executes the entire servlet stack
> again.   It almost seems as if the oracle connection to the database
> is hitting the tomcat server instead of the database.
>
> This is not the only thread displaying this behaviour.   The entire
> thread dump was 100,000 lines and this thread dump was only 4300 lines
> long, so it's a mind-boggling amount of data to sift through.
>
> Here's the start...
>
> [...]
>     at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
>     at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
>     at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
>     at java.lang.Thread.run(Thread.java:745)
> [repeats at least 65 more times...]
> [And here we start repeating again...^^^^....]
>     at java.net.SocketInputStream.socketRead0(Native Method)
>     at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
>     at java.net.SocketInputStream.read(SocketInputStream.java:170)
>     at java.net.SocketInputStream.read(SocketInputStream.java:141)
>     at oracle.net.ns.Packet.receive(Packet.java:300)
>     at oracle.net.ns.DataPacket.receive(DataPacket.java:106)
>     at oracle.net.ns.NetInputStream.getNextPacket(NetInputStream.java:315)
>     at oracle.net.ns.NetInputStream.read(NetInputStream.java:260)
>     at oracle.net.ns.NetInputStream.read(NetInputStream.java:185)
>     at oracle.net.ns.NetInputStream.read(NetInputStream.java:102)
>     at oracle.jdbc.driver.T4CSocketInputStreamWrapper.readNextPacket(T4CSocketInputStreamWrapper.java:124)
>     at oracle.jdbc.driver.T4CSocketInputStreamWrapper.read(T4CSocketInputStreamWrapper.java:80)
>     at oracle.jdbc.driver.T4CMAREngine.unmarshalUB1(T4CMAREngine.java:1137)
>     at oracle.jdbc.driver.T4CTTIfun.receive(T4CTTIfun.java:290)
>     at oracle.jdbc.driver.T4CTTIfun.doRPC(T4CTTIfun.java:192)
>     at oracle.jdbc.driver.T4C7Ocommoncall.doOCOMMIT(T4C7Ocommoncall.java:75)
>     at oracle.jdbc.driver.T4CConnection.doCommit(T4CConnection.java:617)
>     at oracle.jdbc.driver.PhysicalConnection.commit(PhysicalConnection.java:3901)
>     at oracle.jdbc.driver.PhysicalConnection.commit(PhysicalConnection.java:3907)
>     at org.apache.cayenne.conn.ConnectionWrapper.commit(ConnectionWrapper.java:136)
>     at org.apache.cayenne.access.InternalTransaction.processCommit(InternalTransaction.java:73)
>     at org.apache.cayenne.access.ExternalTransaction.commit(ExternalTransaction.java:97)
>     at org.apache.cayenne.access.DataDomain.runInTransaction(DataDomain.java:878)
>     at org.apache.cayenne.access.DataDomain.onSyncNoFilters(DataDomain.java:814)
>     at org.apache.cayenne.access.DataDomain$DataDomainSyncFilterChain.onSync(DataDomain.java:1031)
>     at org.apache.cayenne.access.DataDomain.onSync(DataDomain.java:785)
>     at org.apache.cayenne.access.DataContext.flushToParent(DataContext.java:817)
>     at org.apache.cayenne.access.DataContext.commitChanges(DataContext.java:756)
>     at com.gvea.applications.epay.cayenne.BaseDAOCayenne.update(BaseDAOCayenne.java:338)
>     at com.gvea.applications.epay.cayenne.EbppDAOCayenne.update(EbppDAOCayenne.java:84)
>     at com.gvea.ebpp.business.CayennePageStateLogger.log(CayennePageStateLogger.java:42)
>     at com.gvea.struts.ebpp.framework.Application.onDoRequest(Application.java:302)
>     at com.gvea.servlet.pageStateCache.PageStateManager.onDoRequest(PageStateManager.java:648)
>     at com.gvea.servlet.pageStateCache.PageStateCacheServlet.doRequest(PageStateCacheServlet.java:174)
>     at com.gvea.servlet.pageStateCache.PageStateCacheServlet.doPost(PageStateCacheServlet.java:131)
>     at javax.servlet.http.HttpServlet.service(HttpServlet.java:648)
>     at javax.servlet.http.HttpServlet.service(HttpServlet.java:729)
>     at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:291)
>     at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
>     at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52)
>     at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:239)
>     at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
>     at com.gvea.servlet.filter.LoggingFilter.doFilter(LoggingFilter.java:66)
>     at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:239)
>     at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
>     at fr.xebia.servlet.filter.XForwardedFilter.doFilter(XForwardedFilter.java:899)
>     at fr.xebia.servlet.filter.XForwardedFilter.doFilter(XForwardedFilter.java:915)
>     at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:239)
>     at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
>     at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:219)
>     at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:106)
>     at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:502)
>     at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:142)
>     at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:79)
>     at org.apache.catalina.valves.AbstractAccessLogValve.invoke(AbstractAccessLogValve.java:610)
>     at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:88)
>     at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:518)
>     at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1091)
>     at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:668)
>     at org.apache.coyote.http11.Http11NioProtocol$Http11ConnectionHandler.process(Http11NioProtocol.java:223)
>     at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1517)
>     at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1474)
>     at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
>     at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
>     at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
>     at java.lang.Thread.run(Thread.java:745)
>
> [Start of the thread above]
>
>
> On Fri, Jun 12, 2015 at 11:21 AM, Mike Kienenberger <mk...@gmail.com> wrote:
>> Hmm.   I just remembered that I have a second infrequently-accessed
>> database which is also configured.
>>
>> So I'd really have 3 runtimes * 2 connection pools, so that explains 6 of the 8.
>>
>> Not sure where the other two are from unless I have a 4th runtime that
>> I've overlooked.
>>
>>
>> On Cayenne 4, yes, that's one of my goals this summer -- upgrade to
>> Cayenne 4.  Probably won't happen until July, though.
>>
>>
>> I'm going to add something that will dump all threads when this
>> exception is hit.
>>
>> On Fri, Jun 12, 2015 at 11:15 AM, Andrus Adamchik
>> <an...@objectstyle.org> wrote:
>>>
>>>> On Jun 12, 2015, at 6:09 PM, Mike Kienenberger <mk...@gmail.com> wrote:
>>>>
>>>> And, interestingly enough, I only have 8 "PoolManagerCleanup" threads,
>>>> and not the 9 that I expected.  Maybe they are create-on-demand and
>>>> one of my runtimes hasn't needed it yet?
>>>
>>> There should be 3 actually. One per PoolManager, not one per connection. So something may be going on there.
>>>
>>> FWIW 4.0.M3 (master branch) has a completely new non-blocking alternative to PoolManager. The cleanup process is also more sane there.
>>>
>>> Andrus
>>>