Inspiring

Answered

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

Forum|Forum|12 years ago
November 30, 2013
2 replies
9819 views

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.

This topic has been closed for replies.

Correct answer DCwebGuy

Looks like we're dealing with a network configuration issue. It makes sense, because all the other data is crazy, and finally the whole IT team stayed online late and monitored the whole crash in-processes, and looks like it might have to do with Oracle backups and the network share drive. Something may be locking up the I/O process on the database and preventing communication with all services, so ColdFusion just sits and hangs, connections keep getting opened and never closed (even with Maintain Connections off) so that's the story for now. I am just happy it does not appear to be a bug in ColdFusion or Tomcat, but will keep this thread going until its conclusion just in case this helps anyone else who find themselves in this spot! What a mess! The hours involved in troublshooting this have been astronomical.

Hi, all. My problem was finally solved with changes to our network wiring configuration. Here is the write-up from my IT team explaining exactly what they did:

------------

We performed a few upgrades simultaneously which may have contributed to the current stability. Though the Oracle upgrade and the kernel upgrade / patch may have been factors, it's our opinion that the network port was the primary culprit.

The way that the network was previously configured, each server gained network access through a different switch, which in turn were connected through other devices. The database server stores the databases on the storage cluster, mapped via NFS. By moving the database server network port to the same switch that the storage cluster users, we eliminated extra hops and hardware. Speeds for the database server increased and we stopped seeing timeouts occur.

Before change:

web server -> Switch1 -> Switch2 -> Switch3 -> database server -> Switch3 -> Switch4 -> Switch5 -> storage -> Switch5 -> Switch4 -> Switch3 -> database server -> Switch3 -> Switch2 -> Switch1 -> web server

After change:

web server -> Switch1 -> Switch2 -> Switch3 -> database server -> Switch3 -> storage -> Switch3 -> database server -> Switch3 -> Switch2 -> Switch1 -> web server

------------

I guess the moral of the story here is check your network hops if anyone is experiencing these kinds of ColdFusion/datdabase timeouts and have no idea where they are coming from.

P.S. Big props to Anit for helping me troublshoot every other possibility before I handed it off to the IT team with the conclusion "It's not ColdFusion!". Adobe Support was EXCELLENT.

M

mack_

Participating Frequently

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.

D

DCwebGuyAuthor

Inspiring

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)