You are viewing a plain text version of this content. The canonical link for it is here.
Posted to user@commons.apache.org by Adrian Woodhead <ad...@last.fm> on 2008/06/26 17:00:14 UTC
dbcp blocked on webapp startup
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>
Any advice, tips, help would be really appreciated, I haven't been able
to find anything on the 'net about this.
Regards,
Adrian
---------------------------------------------------------------------
To unsubscribe, e-mail: user-unsubscribe@commons.apache.org
For additional commands, e-mail: user-help@commons.apache.org
Re: dbcp blocked on webapp startup
Posted by Phil Steitz <ph...@steitz.com>.
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>
>
> Any advice, tips, help would be really appreciated, I haven't been
> able to find anything on the 'net about this.
One possible explanation is that initialization of one (all three?) of
your datasources is hanging on validation. That would leave one of the
threads in the validateConnectionFactory method (or
PoolableConnectionFactory.makeObject) waiting on the database connection
or validation query. Can you find such a thread? The others will queue
up waiting for the first requesting thread to create the datasource.
The way it works is that the datasource is created on first activation
of createDatasource and subsequent calls return the instance created on
the first call.
Send me a full thread dump and I will have a look if this does not help.
You will likely also get better throughput if you upgrade to pool 1.4,
though that will not solve the problem above it it is queuing on
datasource creation.
Phil
---------------------------------------------------------------------
To unsubscribe, e-mail: user-unsubscribe@commons.apache.org
For additional commands, e-mail: user-help@commons.apache.org
Re: [dbcp] Contention for DriverManager when initializing multiple
datasources WAS: Re: dbcp blocked on webapp startup
Posted by Adrian Woodhead <ad...@last.fm>.
> But if all the pools are initialised via Spring, and are all non-lazy
> then they should be initialised sequentially by the same spring
> initialisation thread, not in parallel. Spring initialisation is done
> via a servlet ContextListener, and that is guaranteed to be called
> single-threaded.
>
> But in the thread-dumps, we clearly see two threads doing driver
> loading in parallel.
>
> Presumably some of these pooled datasources are not spring-managed?
The thread dumps you saw were from before I made the datasources
non-lazy. The build I deployed today which experienced the same problem
had the 2 postgres datasources set to non-lazy and the mysql datasource
left as lazy. So I find it strange that this had the same issue as, like
you say, I would have expected the postgres datasources to be
initialised in sequence and for this problem to go away for the postgres
datasources but it still happened. I will mark all datasources as
non-lazy and do another thread dump if/when it happens again.
Either way I think it should work in a multithreaded environment without
having to make changes to the initialisation of the datasources so I
will file a bug report like you suggested. Thanks.
Regards,
Adrian
---------------------------------------------------------------------
To unsubscribe, e-mail: user-unsubscribe@commons.apache.org
For additional commands, e-mail: user-help@commons.apache.org
Re: [dbcp] Contention for DriverManager when initializing multiple
datasources WAS: Re: dbcp blocked on webapp startup
Posted by "simon.kitching@chello.at" <si...@chello.at>.
Adrian Woodhead schrieb:
> Simon - thanks for your feedback, what you said makes sense...
>>> The big question is: why are you running dbcp concurrently in two
>>> different
>>> threads?
>>>
>>
>> Two data sources within the same webapp (spring config) perhaps?
>>
> Exactly. There are 3 actually - 2 postgres databases and one mysql
> database, each has its own pooled datasource.
But if all the pools are initialised via Spring, and are all non-lazy
then they should be initialised sequentially by the same spring
initialisation thread, not in parallel. Spring initialisation is done
via a servlet ContextListener, and that is guaranteed to be called
single-threaded.
But in the thread-dumps, we clearly see two threads doing driver loading
in parallel.
Presumably some of these pooled datasources are not spring-managed?
>
>>> Possibly dbcp should call DriverManager.getDrivers() internally on
>>> startup
>>> to avoid this race...
>>>
>>
>> If this would solve it, I'd say it's a must, then. This is a really
>> nasty race condition.
>>
> It is. Should I file a bug? I'd be happy to try out a build with this
> fix in it to see if it helps.
Yes, I would suggest filing a bugreport.
Cheers,
Simon
---------------------------------------------------------------------
To unsubscribe, e-mail: user-unsubscribe@commons.apache.org
For additional commands, e-mail: user-help@commons.apache.org
Re: [dbcp] Contention for DriverManager when initializing multiple
datasources WAS: Re: dbcp blocked on webapp startup
Posted by Adrian Woodhead <ad...@last.fm>.
Simon - thanks for your feedback, what you said makes sense...
>> The big question is: why are you running dbcp concurrently in two different
>> threads?
>>
>
> Two data sources within the same webapp (spring config) perhaps?
>
Exactly. There are 3 actually - 2 postgres databases and one mysql
database, each has its own pooled datasource.
>> Possibly dbcp should call DriverManager.getDrivers() internally on startup
>> to avoid this race...
>>
>
> If this would solve it, I'd say it's a must, then. This is a really
> nasty race condition.
>
It is. Should I file a bug? I'd be happy to try out a build with this
fix in it to see if it helps.
Regards,
Adrian
---------------------------------------------------------------------
To unsubscribe, e-mail: user-unsubscribe@commons.apache.org
For additional commands, e-mail: user-help@commons.apache.org
Re: [dbcp] Contention for DriverManager when initializing multiple datasources WAS: Re: dbcp blocked on webapp startup
Posted by James Carman <ja...@carmanconsulting.com>.
On Tue, Jul 1, 2008 at 7:16 AM, simon.kitching@chello.at
<si...@chello.at> wrote:
> The big question is: why are you running dbcp concurrently in two different
> threads?
Two data sources within the same webapp (spring config) perhaps?
> Possibly dbcp should call DriverManager.getDrivers() internally on startup
> to avoid this race...
If this would solve it, I'd say it's a must, then. This is a really
nasty race condition.
---------------------------------------------------------------------
To unsubscribe, e-mail: user-unsubscribe@commons.apache.org
For additional commands, e-mail: user-help@commons.apache.org
Re: [dbcp] Contention for DriverManager when initializing multiple
datasources WAS: Re: dbcp blocked on webapp startup
Posted by "simon.kitching@chello.at" <si...@chello.at>.
Hmm..you appear to have two threads running dbcp simultaneously.
The first thread is trying to initialise a postgresql driver and
register it with DriverManager. The driver registration is being
triggered from a static initialiser block on the postgresql driver
class, so is executing from within the Class.forName method (and
therefore the postgresql driver Class object is locked by this thread).
The second thread is trying to initialise a mysql driver and register it
with DriverManager. Again, the driver registration is being triggered
from a static initialiser block on the mysql driver class, so the mysql
driver Class object is locked by this thread).
But in both cases, the DriverManager needs to be initialised before
anything can be registered. The first thread appears to have run first,
triggering the initialisation process, and the second thread is blocked
waiting for initialisation of DriverManager to complete before it
registers the mysql driver.
Note that DriverManager initialisation involves searching for all
META-INF/services/java.sql.Driver files and then loading each driver in
turn:
http://java.sun.com/j2se/1.4.2/docs/guide/jar/jar.html#Service%20Provider
But if the mysql driver jarfile contains such a services file, then the
driver manager initialisation process will try to access the MySql
driver Class object - which is locked, waiting for DriverManager
initialisation to return. Result: deadlock.
The big question is: why are you running dbcp concurrently in two
different threads?
Perhaps you have two different webapps that are starting up in parallel
when the servlet container starts, and they both use dbcp, and the
database drivers are in a shared directory? If so, then moving the
database drivers into the webapps might solve this, as then each webapp
will have its own Class object for the driver. Libraries in shared
classpaths are evil and cause many problems.
Alternately, you could force a call to DriverManager.initialize to occur
before dbcp starts, eg via a call to DriverManager.getDrivers().
Possibly dbcp should call DriverManager.getDrivers() internally on
startup to avoid this race...
Cheers,
Simon
Adrian Woodhead schrieb:
> After some discussion with Phil I changed my Spring config to load up
> my datasources on app context startup (by marking them
> lazy-init=false) instead of having them lazily loaded when the
> application has already started when it gets immediately hit by
> hundreds of requests. We thought that by reducing the concurrency for
> creating the resource it would resolve this locking issue.
> Unfortunately this is not the case and I am still seeing exactly the
> same behaviour as below with a RUNNABLE thread in Class.forName
> locking the DriverManager and all the other threads BLOCKED on this.
> Any suggestions on what I can try next?
>> 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):
>>
>
---------------------------------------------------------------------
To unsubscribe, e-mail: user-unsubscribe@commons.apache.org
For additional commands, e-mail: user-help@commons.apache.org
Re: [dbcp] Contention for DriverManager when initializing multiple
datasources WAS: Re: dbcp blocked on webapp startup
Posted by Adrian Woodhead <ad...@last.fm>.
After some discussion with Phil I changed my Spring config to load up my
datasources on app context startup (by marking them lazy-init=false)
instead of having them lazily loaded when the application has already
started when it gets immediately hit by hundreds of requests. We thought
that by reducing the concurrency for creating the resource it would
resolve this locking issue. Unfortunately this is not the case and I am
still seeing exactly the same behaviour as below with a RUNNABLE thread
in Class.forName locking the DriverManager and all the other threads
BLOCKED on this. Any suggestions on what I can try next?
> 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
>
---------------------------------------------------------------------
To unsubscribe, e-mail: user-unsubscribe@commons.apache.org
For additional commands, e-mail: user-help@commons.apache.org
[dbcp] Contention for DriverManager when initializing multiple datasources
WAS: Re: dbcp blocked on webapp startup
Posted by Phil Steitz <ph...@steitz.com>.
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