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/07/01 12:24:13 UTC

Re: [dbcp] Contention for DriverManager when initializing multiple datasources WAS: Re: dbcp blocked on webapp startup

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


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