CF10 database connection BLOCKED?? - JDBCPool.checkOut/checkIn

Report · Nov 30, 2013

I am continuing to troublshoot some 503 issues with my new server. I recently enabled the Dump Snapshot feature inside Server Monitor and whenever I have an Unresponsive Server alert and I am seeing tons of these in the snapshot. Anyone know what this means exactly??

"ajp-bio-8012-exec-384" prio=5 tid=1261 BLOCKED

at coldfusion.server.j2ee.sql.pool.JDBCPool.checkOut(JDBCPool.java:371)

at coldfusion.server.j2ee.sql.pool.JDBCPool.requestConnection(JDBCPool.java:825)

at coldfusion.server.j2ee.sql.pool.JDBCManager.requestConnection(JDBCManager.java:125)

at coldfusion.server.j2ee.sql.JRunDataSource.getConnection(JRunDataSource.java:135)

at coldfusion.sql.CFDataSource.getConnection(CFDataSource.java:42)

at coldfusion.sql.DataSrcImpl.getCachedConnection(DataSrcImpl.java:156)

at coldfusion.sql.DataSrcImpl.getConnection(DataSrcImpl.java:110)

at coldfusion.sql.SqlImpl.execute(SqlImpl.java:363)

at coldfusion.tagext.sql.QueryTag.executeQuery(QueryTag.java:1059)

at coldfusion.tagext.sql.QueryTag.doEndTag(QueryTag.java:688)

at cfpageInitQrygetPortalInfo2ecfm582265125.runPage(E:\pathToMyPage.cfm:24)

ETC...

And something like this during another similar event:

"ajp-bio-8012-exec-127" prio=5 tid=325 BLOCKED

at coldfusion.server.j2ee.pool.ObjectPool.checkIn(ObjectPool.java:263)

at coldfusion.server.j2ee.sql.pool.JDBCPool.returnConnection(JDBCPool.java:851)

at coldfusion.server.j2ee.sql.pool.JDBCPool.connectionClosed(JDBCPool.java:324)

at coldfusion.server.j2ee.sql.JRunConnection.sendCloseEvent(JRunConnection.java:345)

at coldfusion.server.j2ee.sql.JRunConnectionHandle.close(JRunConnectionHandle.java:72)

at coldfusion.sql.DataSrcImpl.clear(DataSrcImpl.java:182)

at coldfusion.sql.DataSrcImpl.clearSqlProxy(DataSrcImpl.java:25)

at coldfusion.filter.DatasourceFilter.invoke(DatasourceFilter.java:26)

at coldfusion.filter.CachingFilter.invoke(CachingFilter.java:62)

at coldfusion.CfmServlet.service(CfmServlet.java:219)

at coldfusion.bootstrap.BootstrapServlet.service(BootstrapServlet.java:89)

at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:305)

at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:210)

at coldfusion.monitor.event.MonitoringServletFilter.doFilter(MonitoringServletFilter.java:42)

at coldfusion.bootstrap.BootstrapFilter.doFilter(BootstrapFilter.java:46)

at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:243)

at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:210)

at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:224)

at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:169)

at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:472)

at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:168)

at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:98)

at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:928)

at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:118)

at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:414)

at org.apache.coyote.ajp.AjpProcessor.process(AjpProcessor.java:204)

at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:539)

at org.apache.tomcat.util.net.JIoEndpoint$SocketProcessor.run(JIoEndpoint.java:298)

at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)

at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)

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

The issues I'm having sound very similar to what's going on here and here but so far I have reached no conclusions. WTH is going on?

I have a brand new 64-bit Win2008/IIS7 machine (well, VMware if it makes any diff) running CF10 with the latest Update 12 patch, etc. I even updated the JRE to the latest version (1.7.0_45 at the time of this writing). I have done the whole Tomcat connector thing, modfied it several times with higher pool sizes, timeouts, etc., reinstalled the connector serveral times (the last being when I updated to CF10 Update 12). The JVM is perfectly configured. I've tried some of Carl's tweaks to no avail. Anit from Adobe Support has been helping me, too, and has done remote desktop sessions and seen my server and says all the settings look good, so he is sort of at a loss too except to analyze my logs whenever I send them, but I am not getting any concrete data that I think will help yet, as I am very familiar with what to look for in general. I've been doing CF for 16 years and never encountered such a stubborn issue.

Report · Dec 02, 2013

Monday morning bump. Please help if anyone knows. This is driving me crazy and locking up my production server several times per day, but mostly at evening/night, which is strange but perhaps telling.

One thing I've been thinking: maybe it has to do with the max number of cached queries? I have set the limit of cached queries to 20,000, and my Server Monitor tells me it is always at the maximum level after running for a day or two. Could it be that the server hangs while it is trying to release the older cached queries in order to insert new queries into the cache? Is 20,000 too much on a 64-bit machine with 8GM of RAM? Memory and CPU definitely do not seem to be an issue on the surface.

Or could it be an issue with a CFLOCK somewhere? If so, I would expect to see errors in the log related to CFLOCK but I do not, and the one or two pages I have with CFLOCK in them run great and by themselves do not seem to cause any problem.

Report · Dec 02, 2013

This looks like a deadlock somewhere inside CF. If you have CF enterprise

you can trigger a snapshot in the Server Monitor and that might give you

more info or if you have CF standard you can start CF from the command line

("coldfusion start console"), attach JVisualm to that ColdFusion intance

and get a thread dump. That thread dump will contain more info about locks

that are held by each thread.

Report · Dec 02, 2013

Hi, Mack. Yes, this is Enterprise. The info above is from the snapshot, which is generated automatically when I get an Unresponsive Server alert from CF and attached to my email. I only pasted what I thought was the relevant part. I don't see anything in the rest of the file about "locks" specifically. What should I be looking for??

Here is what it says at the very top of the snapshot, then underneath are all the specific threads running, and their stack trace dumps. They are all basic requests to the index.cfm page of multiple sites, probably because there is some spider or robot scanning the site, but nothing we can't handle load-wise. I have used JMeter and done stress testing to confirm this.

Snapshot generated on : Sun Dec 01 20:46:01 EST 2013	Caused by : Unresponsive Server Alert
Profiling : Disabled
Memory Tracking : Disabled

8 or more threads are busy for more than 60 seconds.

*Total Running requests - 85

*Total Queued requests - 4

Template Running requests - 85

Template Queued requests - 4

Flash Remoting Running requests - 0

Flash Remoting Queued requests - 0

CFC method Running requests - 0

CFC method Queued requests - 0

Web Service Running requests - 0

Web Service Queued requests - 0

JVM Memory Stats

Free Memory : 507323936 bytes

Used Memory : 787667424 bytes

Throttle Stats [Throttle Queue Size : Throttle Memory Used]

0 : 0.0 megabytes

Query Cache Stats -

[Hit Ratio : Size : Count]

0.0 : 0 bytes : 19927

Cached Queries -

[Query Name : DSN : Size : TIme Executed : Time Taken : Line No : Function Name : Template Path]

DB Pool Stats -

[DSN :Open Conn Count : Total Conn Count : Max Con Count : Avg Open Conn Count : Avg Total Conn Count]

DSN1 : 0 : 1 : Unlimited : 0 : 6

DSN2 : 0 : 0 : Unlimited : 0 : 0

DSN3 : 2 : 3 : Unlimited : 2 : 3

DSN4 : 0 : 1 : Unlimited : 0 : 18

DSN5 : 0 : 0 : Unlimited : 0 : 0

DSN6 : 0 : 1 : Unlimited : 0 : 1

DSN7 : 0 : 0 : Unlimited : 0 : 0

DSN8 : 37 : 37 : Unlimited : 31 : 43

DSN9 : 0 : 0 : Unlimited : 0 : 0

DSN10 : 0 : 1 : Unlimited : 0 : 0

DSN11 : 0 : 0 : Unlimited : 0 : 0

DSN12 : 0 : 1 : Unlimited : 0 : 0

DSN13 : 0 : 1 : Unlimited : 0 : 1

DSN14 : 0 : 2 : Unlimited : 0 : 1

Then a list of the 85 threads/pages (in this case they are all index.cfm for one or more of our sites--we only have a few).

Then a list of the actual FULL thread dump. Here is more from the same file:

Java stack trace -

Full thread dump Java 1.7.0_45

"ajp-bio-8012-exec-482" prio=5 tid=1092 TIMED_WAITING

at sun.misc.Unsafe.park(Native Method)

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.java:1068)

at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130)

at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)

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

"ajp-bio-8012-exec-523" prio=5 tid=1139 BLOCKED

at coldfusion.server.j2ee.sql.pool.JDBCPool.checkOut(JDBCPool.java:371)

at coldfusion.server.j2ee.sql.pool.JDBCPool.requestConnection(JDBCPool.java:825)

at coldfusion.server.j2ee.sql.pool.JDBCManager.requestConnection(JDBCManager.java:125)

at coldfusion.server.j2ee.sql.JRunDataSource.getConnection(JRunDataSource.java:135)

at coldfusion.sql.CFDataSource.getConnection(CFDataSource.java:42)

at coldfusion.sql.DataSrcImpl.getCachedConnection(DataSrcImpl.java:156)

at coldfusion.sql.DataSrcImpl.getConnection(DataSrcImpl.java:110)

at coldfusion.sql.SqlImpl.execute(SqlImpl.java:363)

at coldfusion.tagext.sql.QueryTag.executeQuery(QueryTag.java:1059)

at coldfusion.tagext.sql.QueryTag.doEndTag(QueryTag.java:688)

at cfpageInitQrygetPortalInfo2ecfm582265125.runPage(E:\Inetpub\mySite1\Queries\pageInitQrygetPortalInfo.cfm:24)

at coldfusion.runtime.CfJspPage.invoke(CfJspPage.java:244)

at coldfusion.tagext.lang.IncludeTag.doStartTag(IncludeTag.java:444)

at coldfusion.runtime.CfJspPage._emptyTcfTag(CfJspPage.java:2799)

at cfpageInit2ecfm1741799151.runPage(E:\Inetpub\mySite1\Includes\pageInit.cfm:70)

at coldfusion.runtime.CfJspPage.invoke(CfJspPage.java:244)

at coldfusion.tagext.lang.IncludeTag.doStartTag(IncludeTag.java:444)

at coldfusion.runtime.CfJspPage._emptyTcfTag(CfJspPage.java:2799)

at cfpage2ecfm2105009432.runPage(E:\Inetpub\mySite1\page.cfm:21)

at coldfusion.runtime.CfJspPage.invoke(CfJspPage.java:244)

at coldfusion.tagext.lang.IncludeTag.doStartTag(IncludeTag.java:444)

at coldfusion.filter.CfincludeFilter.invoke(CfincludeFilter.java:65)

at coldfusion.filter.IpFilter.invoke(IpFilter.java:64)

at coldfusion.filter.ApplicationFilter.invoke(ApplicationFilter.java:449)

at coldfusion.filter.RequestMonitorFilter.invoke(RequestMonitorFilter.java:48)

at coldfusion.filter.MonitoringFilter.invoke(MonitoringFilter.java:40)

at coldfusion.filter.PathFilter.invoke(PathFilter.java:112)

at coldfusion.filter.ExceptionFilter.invoke(ExceptionFilter.java:94)

at coldfusion.filter.ClientScopePersistenceFilter.invoke(ClientScopePersistenceFilter.java:28)

at coldfusion.filter.BrowserFilter.invoke(BrowserFilter.java:38)

at coldfusion.filter.NoCacheFilter.invoke(NoCacheFilter.java:58)

at coldfusion.filter.GlobalsFilter.invoke(GlobalsFilter.java:38)

at coldfusion.filter.DatasourceFilter.invoke(DatasourceFilter.java:22)