commons-user mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Phil Steitz <p...@steitz.com>
Subject [dbcp] Contention for DriverManager when initializing multiple datasources WAS: Re: dbcp blocked on webapp startup
Date Sat, 28 Jun 2008 17:00:30 GMT
Adrian Woodhead wrote:
> Hey there,
>
> I am experiencing some odd behaviour related to DBCP. We have an 
> application that is deployed in Tomcat 6.0.16 on Linux with Java 6. It 
> uses dbcp 1.2.2 (with commons pool 1.3) and we have a pooled 
> datasource configured in spring which is in turn used by ibatis. This 
> webapp receives around 300-600 requests per second. When we deploy new 
> versions of the app we restart tomcat from scratch and it *usually* 
> stars up just fine. However, every now and then (say 20% of the time) 
> it starts up, runs OK for less than a minute and then just freezes up. 
> I did a stack dump at this point and see many BLOCKED threads all 
> blocked in the same spot (BasicDataSource line 1123 where is creates a 
> datasource and returns it). Here is a portion of the thread dump 
> showing the symptom:
>
> "http-80-15" daemon prio=10 tid=0x00002aaaf51f8800 nid=0x1bfa waiting 
> for monitor entry [0x0000000043158000..0x0000000043159d40]
>   java.lang.Thread.State: BLOCKED (on object monitor)
>    at 
> org.apache.commons.dbcp.BasicDataSource.createDataSource(BasicDataSource.java:1123) 
>
>    - waiting to lock <0x00002aaab58758a8> (a 
> org.apache.commons.dbcp.BasicDataSource)
>    at 
> org.apache.commons.dbcp.BasicDataSource.getConnection(BasicDataSource.java:880) 
>
>    at 
> org.springframework.jdbc.datasource.DataSourceUtils.doGetConnection(DataSourceUtils.java:113)

>
>    at 
> org.springframework.jdbc.datasource.TransactionAwareDataSourceProxy$TransactionAwareInvocationHandler.invoke(TransactionAwareDataSourceProxy.java:210)

>
>    at $Proxy0.prepareStatement(Unknown Source)
>    at 
> com.ibatis.sqlmap.engine.execution.SqlExecutor.prepareStatement(SqlExecutor.java:494)

>
>    at 
> com.ibatis.sqlmap.engine.execution.SqlExecutor.executeQuery(SqlExecutor.java:176) 
>
>    at 
> com.ibatis.sqlmap.engine.mapping.statement.GeneralStatement.sqlExecuteQuery(GeneralStatement.java:205)

>
>    at 
> com.ibatis.sqlmap.engine.mapping.statement.GeneralStatement.executeQueryWithCallback(GeneralStatement.java:173)

>
>    at 
> com.ibatis.sqlmap.engine.mapping.statement.GeneralStatement.executeQueryForObject(GeneralStatement.java:104)

>
>    at 
> com.ibatis.sqlmap.engine.impl.SqlMapExecutorDelegate.queryForObject(SqlMapExecutorDelegate.java:566)

>
>    at 
> com.ibatis.sqlmap.engine.impl.SqlMapExecutorDelegate.queryForObject(SqlMapExecutorDelegate.java:541)

>
>    at 
> com.ibatis.sqlmap.engine.impl.SqlMapSessionImpl.queryForObject(SqlMapSessionImpl.java:106)

>
>    at 
> com.ibatis.sqlmap.engine.impl.SqlMapClientImpl.queryForObject(SqlMapClientImpl.java:83)

>
>    at 
> post.audioscrobbler.submission.dao.ibatis.IbatisCatalogueDao.getAlbumId(IbatisCatalogueDao.java:273)

>
>    at 
> post.audioscrobbler.submission.realtime.SubmissionRequestHandler1_2.handleRequest(SubmissionRequestHandler1_2.java:106)

>
>    at 
> post.audioscrobbler.submission.realtime.SubmissionServlet1_2.handleRequest(SubmissionServlet1_2.java:177)

>
>    at 
> post.audioscrobbler.submission.realtime.SubmissionServlet1_2.handleSubmission(SubmissionServlet1_2.java:134)

>
>    at 
> post.audioscrobbler.submission.realtime.BaseSubmissionServlet.doPost(BaseSubmissionServlet.java:131)

>
>    at 
> post.audioscrobbler.submission.realtime.SubmissionServlet1_2.doPost(SubmissionServlet1_2.java:26)

>
>    at javax.servlet.http.HttpServlet.service(HttpServlet.java:710)
>    at javax.servlet.http.HttpServlet.service(HttpServlet.java:803)
>    at 
> org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290)

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

>
>    at 
> org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:233) 
>
>    at 
> org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:175) 
>
>    at 
> org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:128) 
>
>    at 
> org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102) 
>
>    at 
> org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109) 
>
>    at 
> org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:286) 
>
>    at 
> org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:844) 
>
>    at 
> org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:583)

>
>    at 
> org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:447)
>    at java.lang.Thread.run(Thread.java:619)
>
> At this point we have to restart tomcat and hope everything goes ok 
> the next startup. Does anybody have any idea what could be causing 
> this? Are we doing something wrong with our settings? We have 3 data 
> sources defined (2 postgres, 1 mysql) all using dbcp configured 
> similarly and I see threads in the BLOCKED state at the same line for 
> all 3 of them. Here is our config for one of them:
>
>  <bean id="catSlaveDataSource" 
> class="org.apache.commons.dbcp.BasicDataSource">
>    <property name="driverClassName" value="org.postgresql.Driver"/>
>    <property name="url" value="${db.catslave.url}"/>
>    <property name="username" value="${db.catslave.username}"/>
>    <property name="password" value="${db.catslave.password}"/>
>    <property name="maxActive" value="25"/>
>    <property name="maxIdle" value="10"/>
>    <property name="maxWait" value="1000"/>
>    <property name="testOnBorrow" value="true"/>
>    <property name="testOnReturn" value="true"/>
>    <property name="validationQuery" value="select version();"/>
>  </bean>
>
After getting a full thread dump offline, I think the problem may be here:

"http-80-5" daemon prio=10 tid=0x00002aaaf4f87000 nid=0x1bf0 in 
Object.wait() [0x000000004274d000..0x000000004274fe40]
   java.lang.Thread.State: RUNNABLE
    at java.lang.Class.forName0(Native Method)
    at java.lang.Class.forName(Class.java:247)
    at sun.misc.Service$LazyIterator.next(Service.java:271)
    at java.sql.DriverService.run(DriverManager.java:664)
    at java.security.AccessController.doPrivileged(Native Method)
    at java.sql.DriverManager.loadInitialDrivers(DriverManager.java:506)
    at java.sql.DriverManager.initialize(DriverManager.java:612)
    at java.sql.DriverManager.registerDriver(DriverManager.java:281)
    - locked <0x00002aaaafcced80> (a java.lang.Class for 
java.sql.DriverManager)
    at org.postgresql.Driver.<clinit>(Driver.java:66)
    at java.lang.Class.forName0(Native Method)
    at java.lang.Class.forName(Class.java:169)
    at 
org.apache.commons.dbcp.BasicDataSource.createDataSource(BasicDataSource.java:1130)
    - locked <0x00002aaab58758a8> (a 
org.apache.commons.dbcp.BasicDataSource)
    ...

"http-80-31" daemon prio=10 tid=0x00002aaaf5484400 nid=0x1c0a waiting 
for monitor entry [0x0000000040d34000..0x0000000040d35d40]
   java.lang.Thread.State: BLOCKED (on object monitor)
    at java.sql.DriverManager.registerDriver(DriverManager.java:280)
    - waiting to lock <0x00002aaaafcced80> (a java.lang.Class for 
java.sql.DriverManager)
    at com.mysql.jdbc.Driver.<clinit>(Driver.java:62)
    at java.lang.Class.forName0(Native Method)
    at java.lang.Class.forName(Class.java:169)
    at 
org.apache.commons.dbcp.BasicDataSource.createDataSource(BasicDataSource.java:1130)
    - locked <0x00002aaab59d97b8> (a 
org.apache.commons.dbcp.BasicDataSource)
    at 
org.apache.commons.dbcp.BasicDataSource.getConnection(BasicDataSource.java:880)
    ...

Other threads pile up in state above waiting for the datasources to be 
initialized.  I am not sure if this is
a) a DBCP JDBC 4 compat bug - i.e., we should not be using Class.forName 
with no synch on the DriverManager in BasicDataSource.createDataSource. 
b) a JDK bug or "feature" (why do we see loadInitialDrivers in the first 
trace above?)
c) a driver bug

Any thoughts on this?   Why is the first thread RUNNABLE, but apparently 
hung? 

JDK is
Java HotSpot(TM) 64-Bit Server VM (1.6.0-b105 mixed mode):

Phil
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: user-unsubscribe@commons.apache.org
> For additional commands, e-mail: user-help@commons.apache.org
>


---------------------------------------------------------------------
To unsubscribe, e-mail: user-unsubscribe@commons.apache.org
For additional commands, e-mail: user-help@commons.apache.org


Mime
View raw message