#26 awaitAcquire / Connection pool drops to 0?

closed
nobody
None
5
2014-10-16
2006-05-04
Anonymous
No

I'm using c3p0 9.0.4 with hibernate 3.0.4 and MySQL 4.1

I successfully run a load test for 48 hours with ~10M
DB operations through c3p0 (way to go!). However, 30
minutes after the test ended the system died on a
simpler test because c3p0 does not create new DB
connections. The error I get is "TimeoutException:
internal -- timeout at awaitAcquire()"

Digging in I found that once it became idle, c3p0
cleared the connection pool so it has 0 connections
(below my setting of hibernate.c3p0.max_size=3 !!!).

Once it dropped below 0, it never makes any new
connection. All requests for new connections just time
out. A full restart is required to exist this state.

My c3p0 configuration is:

hibernate.c3p0.min_size=1
hibernate.c3p0.max_size=100
hibernate.c3p0.max_statements=100
hibernate.c3p0.timeout=60
hibernate.c3p0.timeout=60
hibernate.c3p0.acquire_increment=1
hibernate.c3p0.idle_test_period=600

In c3p0.properties:
c3p0.checkoutTimeout=120000

I will appreciate any help!

Discussion

  • Steve Waldman
    Steve Waldman
    2006-05-05

    Logged In: YES
    user_id=175530

    Hi.

    This is certainly very peculiar behavior. Obviously,
    under no circumstance should the pool size drop
    to below minPoolSize without reacquisition attempts
    being triggered, and even at pool size zero, a client
    attempt should trigger a reacquisition attempt.

    I'll look into this. Could you please try to replicate
    this behavior under c3p0-0.9.1-pre6. Pool size
    management is radically overhauled in the 0.9.1 series.
    I wonder if the (mis)behavior persists.

    Thanks!

     
  • Logged In: NO

    I too, am experiencing this problem. I am using the c3p0
    binary that comes with Hibernate 3.1.3.

    Here is the C3PO output that shows the behaviour:

    2006-08-07 17:09:41,602 [Timer-0] DEBUG - Checking for
    expired resources - Mon Aug 07 17:09:41 EST 2006
    [com.mchange.v2.resourcepool.BasicResour
    cePool@14d1d41]
    2006-08-07 17:09:41,603 [Timer-0] DEBUG - EXPIRED
    resource:
    com.mchange.v2.c3p0.impl.NewPooledConnection@1362ca8 --->
    age: 65193 max: 60000 [c
    om.mchange.v2.resourcepool.BasicResourcePool@14d1d41]
    2006-08-07 17:09:41,603 [Timer-0] DEBUG - Removing expired
    resource:
    com.mchange.v2.c3p0.impl.NewPooledConnection@1362ca8
    [com.mchange.v2.resour
    cepool.BasicResourcePool@14d1d41]
    2006-08-07 17:09:41,603 [Timer-0] DEBUG - trace
    com.mchange.v2.resourcepool.BasicResourcePool@14d1d41
    [managed: 5, unused: 5, excluded: 0] (e.g.
    com.mchange.v2.c3p0.impl.NewPooledConnection@1ae90c)
    2006-08-07 17:09:41,603
    [com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#0]
    DEBUG - ENTER METHOD: closeAll( com.sybase.jdbc2.jdbc.
    SybConnection@df574d )! -- num_connections: 6
    2006-08-07 17:09:41,603 [Timer-0] DEBUG - EXPIRED
    resource:
    com.mchange.v2.c3p0.impl.NewPooledConnection@779d17 --->
    age: 65116 max: 60000 [co
    m.mchange.v2.resourcepool.BasicResourcePool@14d1d41]
    2006-08-07 17:09:41,603
    [com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#0]
    DEBUG - Set of statements for connection: [com.sybase.
    jdbc2.jdbc.SybPreparedStatement@124b62a,
    com.sybase.jdbc2.jdbc.SybPreparedStatement@12eddc0,
    com.sybase.jdbc2.jdbc.SybPreparedStatement@1f01381,
    com.sybase.jdbc2.jdbc.SybPreparedStatement@f687a3]; size:
    4
    2006-08-07 17:09:41,603 [Timer-0] DEBUG - Removing expired
    resource:
    com.mchange.v2.c3p0.impl.NewPooledConnection@779d17
    [com.mchange.v2.resourc
    epool.BasicResourcePool@14d1d41]
    2006-08-07 17:09:41,604 [Timer-0] DEBUG - trace
    com.mchange.v2.resourcepool.BasicResourcePool@14d1d41
    [managed: 4, unused: 4, excluded: 0] (e.g.
    com.mchange.v2.c3p0.impl.NewPooledConnection@1ae90c)
    2006-08-07 17:09:41,604
    [com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#2]
    DEBUG - ENTER METHOD: closeAll( com.sybase.jdbc2.jdbc.
    SybConnection@17ba2e9 )! -- num_connections: 5
    2006-08-07 17:09:41,604 [Timer-0] DEBUG - EXPIRED
    resource:
    com.mchange.v2.c3p0.impl.NewPooledConnection@25211b --->
    age: 65033 max: 60000 [co
    m.mchange.v2.resourcepool.BasicResourcePool@14d1d41]
    2006-08-07 17:09:41,604
    [com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#2]
    DEBUG - Set of statements for connection: [com.sybase.
    jdbc2.jdbc.SybPreparedStatement@b7b831,
    com.sybase.jdbc2.jdbc.SybPreparedStatement@19c1f49,
    com.sybase.jdbc2.jdbc.SybPreparedStatement@1c9edf0,
    com.sybase.jdbc2.jdbc.SybPreparedStatement@146b111]; size:
    4
    2006-08-07 17:09:41,604 [Timer-0] DEBUG - Removing expired
    resource:
    com.mchange.v2.c3p0.impl.NewPooledConnection@25211b
    [com.mchange.v2.resourc
    epool.BasicResourcePool@14d1d41]
    2006-08-07 17:09:41,605 [Timer-0] DEBUG - trace
    com.mchange.v2.resourcepool.BasicResourcePool@14d1d41
    [managed: 3, unused: 3, excluded: 0] (e.g.
    com.mchange.v2.c3p0.impl.NewPooledConnection@1ae90c)
    2006-08-07 17:09:41,605 [Timer-0] DEBUG - EXPIRED
    resource:
    com.mchange.v2.c3p0.impl.NewPooledConnection@ea7211 --->
    age: 64933 max: 60000 [co
    m.mchange.v2.resourcepool.BasicResourcePool@14d1d41]
    2006-08-07 17:09:41,605 [Timer-0] DEBUG - Removing expired
    resource:
    com.mchange.v2.c3p0.impl.NewPooledConnection@ea7211
    [com.mchange.v2.resourc
    epool.BasicResourcePool@14d1d41]
    2006-08-07 17:09:41,605 [Timer-0] DEBUG - trace
    com.mchange.v2.resourcepool.BasicResourcePool@14d1d41
    [managed: 2, unused: 2, excluded: 0] (e.g.
    com.mchange.v2.c3p0.impl.NewPooledConnection@1ae90c)
    2006-08-07 17:09:41,605 [Timer-0] DEBUG - EXPIRED
    resource:
    com.mchange.v2.c3p0.impl.NewPooledConnection@163058b --->
    age: 64841 max: 60000 [c
    om.mchange.v2.resourcepool.BasicResourcePool@14d1d41]
    2006-08-07 17:09:41,605 [Timer-0] DEBUG - Removing expired
    resource:
    com.mchange.v2.c3p0.impl.NewPooledConnection@163058b
    [com.mchange.v2.resour
    cepool.BasicResourcePool@14d1d41]
    2006-08-07 17:09:41,606 [Timer-0] DEBUG - trace
    com.mchange.v2.resourcepool.BasicResourcePool@14d1d41
    [managed: 1, unused: 1, excluded: 0] (e.g.
    com.mchange.v2.c3p0.impl.NewPooledConnection@1ae90c)
    2006-08-07 17:09:41,606 [Timer-0] DEBUG - EXPIRED
    resource:
    com.mchange.v2.c3p0.impl.NewPooledConnection@1e5a0cf --->
    age: 64755 max: 60000 [c
    om.mchange.v2.resourcepool.BasicResourcePool@14d1d41]
    2006-08-07 17:09:41,606 [Timer-0] DEBUG - Removing expired
    resource:
    com.mchange.v2.c3p0.impl.NewPooledConnection@1e5a0cf
    [com.mchange.v2.resour
    cepool.BasicResourcePool@14d1d41]
    2006-08-07 17:09:41,606 [Timer-0] DEBUG - trace
    com.mchange.v2.resourcepool.BasicResourcePool@14d1d41
    [managed: 0, unused: 0, excluded: 0] (e.g.
    com.mchange.v2.c3p0.impl.NewPooledConnection@1ae90c)
    2006-08-07 17:09:41,612
    [com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#0]
    DEBUG - closeAll(): com.mchange.v2.c3p0.stmt.PerConnec
    tionMaxOnlyStatementCache stats -- total size: 16; checked
    out: 0; num connections: 4; num keys: 16
    2006-08-07 17:09:41,614
    [com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#0]
    DEBUG - ENTER METHOD: closeAll( com.sybase.jdbc2.jdbc.
    SybConnection@1b7a8c5 )! -- num_connections: 4
    2006-08-07 17:09:41,614
    [com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#0]
    DEBUG - Set of statements for connection: [com.sybase.
    jdbc2.jdbc.SybPreparedStatement@12b76b9,
    com.sybase.jdbc2.jdbc.SybPreparedStatement@143c268,
    com.sybase.jdbc2.jdbc.SybPreparedStatement@17f493,
    com.sybase.jdbc2.jdbc.SybPreparedStatement@1962cfa]; size:
    4
    2006-08-07 17:09:41,617
    [com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#1]
    DEBUG - ENTER METHOD: closeAll( com.sybase.jdbc2.jdbc.
    SybConnection@1c6a374 )! -- num_connections: 3
    2006-08-07 17:09:41,618
    [com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#1]
    DEBUG - Set of statements for connection: [com.sybase.
    jdbc2.jdbc.SybPreparedStatement@13fc0bb,
    com.sybase.jdbc2.jdbc.SybPreparedStatement@198f08c,
    com.sybase.jdbc2.jdbc.SybPreparedStatement@10a1b36,
    com.sybase.jdbc2.jdbc.SybPreparedStatement@e2e29c]; size:
    4
    2006-08-07 17:09:41,618
    [com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#2]
    DEBUG - closeAll(): com.mchange.v2.c3p0.stmt.PerConnec
    tionMaxOnlyStatementCache stats -- total size: 8; checked
    out: 0; num connections: 2; num keys: 8
    2006-08-07 17:09:41,619
    [com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#2]
    DEBUG - ENTER METHOD: closeAll( com.sybase.jdbc2.jdbc.
    SybConnection@1c995f6 )! -- num_connections: 2
    2006-08-07 17:09:41,619
    [com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#2]
    DEBUG - Set of statements for connection: [com.sybase.
    jdbc2.jdbc.SybPreparedStatement@e4445e,
    com.sybase.jdbc2.jdbc.SybPreparedStatement@671d0d,
    com.sybase.jdbc2.jdbc.SybPreparedStatement@118ae23, c
    om.sybase.jdbc2.jdbc.SybPreparedStatement@b874d2]; size: 4
    2006-08-07 17:09:49,238 [Timer-0] DEBUG - Checking for
    expired resources - Mon Aug 07 17:09:49 EST 2006
    [com.mchange.v2.resourcepool.BasicResour
    cePool@14d1d41]
    2006-08-07 17:09:56,740 [Timer-0] DEBUG - Checking for
    expired resources - Mon Aug 07 17:09:56 EST 2006
    [com.mchange.v2.resourcepool.BasicResour
    cePool@14d1d41]
    2006-08-07 17:10:04,242 [Timer-0] DEBUG - Checking for
    expired resources - Mon Aug 07 17:10:04 EST 2006
    [com.mchange.v2.resourcepool.BasicResour
    cePool@14d1d41]
    2006-08-07 17:10:11,743 [Timer-0] DEBUG - Checking for
    expired resources - Mon Aug 07 17:10:11 EST 2006
    [com.mchange.v2.resourcepool.BasicResour
    cePool@14d1d41]
    2006-08-07 17:10:19,247 [Timer-0] DEBUG - Checking for
    expired resources - Mon Aug 07 17:10:19 EST 2006
    [com.mchange.v2.resourcepool.BasicResour
    cePool@14d1d41]
    2006-08-07 17:10:26,749 [Timer-0] DEBUG - Checking for
    expired resources - Mon Aug 07 17:10:26 EST 2006
    [com.mchange.v2.resourcepool.BasicResour
    cePool@14d1d41]
    2006-08-07 17:10:34,251 [Timer-0] DEBUG - Checking for
    expired resources - Mon Aug 07 17:10:34 EST 2006
    [com.mchange.v2.resourcepool.BasicResour
    cePool@14d1d41]
    2006-08-07 17:10:41,753 [Timer-0] DEBUG - Checking for
    expired resources - Mon Aug 07 17:10:41 EST 2006
    [com.mchange.v2.resourcepool.BasicResour
    cePool@14d1d41]
    2006-08-07 17:10:49,363 [Timer-0] DEBUG - Checking for
    expired resources - Mon Aug 07 17:10:49 EST 2006
    [com.mchange.v2.resourcepool.BasicResour
    cePool@14d1d41]
    2006-08-07 17:10:56,865 [Timer-0] DEBUG - Checking for
    expired resources - Mon Aug 07 17:10:56 EST 2006
    [com.mchange.v2.resourcepool.BasicResour
    cePool@14d1d41]
    2006-08-07 17:11:04,367 [Timer-0] DEBUG - Checking for
    expired resources - Mon Aug 07 17:11:04 EST 2006
    [com.mchange.v2.resourcepool.BasicResour
    cePool@14d1d41]
    2006-08-07 17:11:11,869 [Timer-0] DEBUG - Checking for
    expired resources - Mon Aug 07 17:11:11 EST 2006
    [com.mchange.v2.resourcepool.BasicResour
    cePool@14d1d41]
    2006-08-07 17:11:19,373 [Timer-0] DEBUG - Checking for
    expired resources - Mon Aug 07 17:11:19 EST 2006
    [com.mchange.v2.resourcepool.BasicResour
    cePool@14d1d41]
    2006-08-07 17:11:26,875 [Timer-0] DEBUG - Checking for
    expired resources - Mon Aug 07 17:11:26 EST 2006
    [com.mchange.v2.resourcepool.BasicResour
    cePool@14d1d41]
    2006-08-07 17:11:34,376 [Timer-0] DEBUG - Checking for
    expired resources - Mon Aug 07 17:11:34 EST 2006
    [com.mchange.v2.resourcepool.BasicResour
    cePool@14d1d41]
    2006-08-07 17:11:41,878 [Timer-0] DEBUG - Checking for
    expired resources - Mon Aug 07 17:11:41 EST 2006
    [com.mchange.v2.resourcepool.BasicResour
    cePool@14d1d41]
    2006-08-07 17:11:49,490 [Timer-0] DEBUG - Checking for
    expired resources - Mon Aug 07 17:11:49 EST 2006
    [com.mchange.v2.resourcepool.BasicResour
    cePool@14d1d41]

    2006-08-07 17:14:19,787 [Timer-0] DEBUG - Checking for
    expired resources - Mon Aug 07 17:14:19 EST 2006
    [com.mchange.v2.resourcepool.BasicResour
    cePool@14d1d41]
    2006-08-07 17:14:27,289 [Timer-0] DEBUG - Checking for
    expired resources - Mon Aug 07 17:14:27 EST 2006
    [com.mchange.v2.resourcepool.BasicResour
    cePool@14d1d41]
    2006-08-07 17:14:34,790 [Timer-0] DEBUG - Checking for
    expired resources - Mon Aug 07 17:14:34 EST 2006
    [com.mchange.v2.resourcepool.BasicResour
    cePool@14d1d41]
    2006-08-07 17:14:39,066 [Timer-0] DEBUG - Refurbishing
    idle resources - Mon Aug 07 17:14:39 EST 2006
    [com.mchange.v2.resourcepool.BasicResourceP
    ool@14d1d41]
    2006-08-07 17:14:39,066 [Timer-0] DEBUG - trace
    com.mchange.v2.resourcepool.BasicResourcePool@14d1d41
    [managed: 0, unused: 0, excluded: 0] (e.g.
    com.mchange.v2.c3p0.impl.NewPooledConnection@1ae90c)
    2006-08-07 17:14:42,292 [Timer-0] DEBUG - Checking for
    expired resources - Mon Aug 07 17:14:42 EST 2006
    [com.mchange.v2.resourcepool.BasicResour
    cePool@14d1d41]
    2006-08-07 17:14:49,913 [Timer-0] DEBUG - Checking for
    expired resources - Mon Aug 07 17:14:49 EST 2006
    [com.mchange.v2.resourcepool.BasicResour
    cePool@14d1d41]

    2006-08-07 17:19:35,441 [Timer-0] DEBUG - Checking for
    expired resources - Mon Aug 07 17:19:35 EST 2006
    [com.mchange.v2.resourcepool.BasicResour
    cePool@14d1d41]
    2006-08-07 17:19:39,068 [Timer-0] DEBUG - Refurbishing
    idle resources - Mon Aug 07 17:19:39 EST 2006
    [com.mchange.v2.resourcepool.BasicResourceP
    ool@14d1d41]
    2006-08-07 17:19:39,068 [Timer-0] DEBUG - trace
    com.mchange.v2.resourcepool.BasicResourcePool@14d1d41
    [managed: 0, unused: 0, excluded: 0] (e.g.
    com.mchange.v2.c3p0.impl.NewPooledConnection@1ae90c)
    2006-08-07 17:19:42,944 [Timer-0] DEBUG - Checking for
    expired resources - Mon Aug 07 17:19:42 EST 2006
    [com.mchange.v2.resourcepool.BasicResour
    cePool@14d1d41]
    2006-08-07 17:19:50,572 [Timer-0] DEBUG - Checking for
    expired resources - Mon Aug 07 17:19:50 EST 2006
    [com.mchange.v2.resourcepool.BasicResour
    cePool@14d1d41]
    2006-08-07 17:19:58,073 [Timer-0] DEBUG - Checking for
    expired resources - Mon Aug 07 17:19:58 EST 2006
    [com.mchange.v2.resourcepool.BasicResour
    cePool@14d1d41]

    2006-08-07 17:24:39,070 [Timer-0] DEBUG - Refurbishing
    idle resources - Mon Aug 07 17:24:39 EST 2006
    [com.mchange.v2.resourcepool.BasicResourceP
    ool@14d1d41]
    2006-08-07 17:24:39,070 [Timer-0] DEBUG - trace
    com.mchange.v2.resourcepool.BasicResourcePool@14d1d41
    [managed: 0, unused: 0, excluded: 0] (e.g.
    com.mchange.v2.c3p0.impl.NewPooledConnection@1ae90c)
    2006-08-07 17:24:43,590 [Timer-0] DEBUG - Checking for
    expired resources - Mon Aug 07 17:24:43 EST 2006
    [com.mchange.v2.resourcepool.BasicResour
    cePool@14d1d41]
    2006-08-07 17:24:51,219 [Timer-0] DEBUG - Checking for
    expired resources - Mon Aug 07 17:24:51 EST 2006
    [com.mchange.v2.resourcepool.BasicResour
    cePool@14d1d41]
    2006-08-07 17:24:58,720 [Timer-0] DEBUG - Checking for
    expired resources - Mon Aug 07 17:24:58 EST 2006
    [com.mchange.v2.resourcepool.BasicResour
    cePool@14d1d41]
    2006-08-07 17:25:06,221 [Timer-0] DEBUG - Checking for
    expired resources - Mon Aug 07 17:25:06 EST 2006
    [com.mchange.v2.resourcepool.BasicResour
    cePool@14d1d41]
    2006-08-07 17:25:13,722 [Timer-0] DEBUG - Checking for
    expired resources - Mon Aug 07 17:25:13 EST 2006
    [com.mchange.v2.resourcepool.BasicResour
    cePool@14d1d41]
    2006-08-07 17:25:17,395 [DeliveryReceiptJMSConsumer1]
    DEBUG - awaitAvailable():
    com.mchange.v2.c3p0.impl.NewPooledConnection@1ae90c
    2006-08-07 17:25:17,395 [DeliveryReceiptJMSConsumer1]
    DEBUG - trace
    com.mchange.v2.resourcepool.BasicResourcePool@14d1d41
    [managed: 0, unused: 0
    , excluded: 0] (e.g.
    com.mchange.v2.c3p0.impl.NewPooledConnection@1ae90c)
    2006-08-07 17:25:20,012 [DeliveryReceiptJMSConsumer2]
    DEBUG - awaitAvailable():
    com.mchange.v2.c3p0.impl.NewPooledConnection@1ae90c
    2006-08-07 17:25:20,012 [DeliveryReceiptJMSConsumer2]
    DEBUG - trace
    com.mchange.v2.resourcepool.BasicResourcePool@14d1d41
    [managed: 0, unused: 0
    , excluded: 0] (e.g.
    com.mchange.v2.c3p0.impl.NewPooledConnection@1ae90c)
    2006-08-07 17:25:21,224 [Timer-0] DEBUG - Checking for
    expired resources - Mon Aug 07 17:25:21 EST 2006
    [com.mchange.v2.resourcepool.BasicResour
    cePool@14d1d41]
    2006-08-07 17:25:28,726 [Timer-0] DEBUG - Checking for
    expired resources - Mon Aug 07 17:25:28 EST 2006
    [com.mchange.v2.resourcepool.BasicResour
    cePool@14d1d41]
    2006-08-07 17:25:35,327 [DeliveryReceiptJMSConsumer3]
    DEBUG - awaitAvailable():
    com.mchange.v2.c3p0.impl.NewPooledConnection@1ae90c
    2006-08-07 17:25:35,327 [DeliveryReceiptJMSConsumer3]
    DEBUG - trace
    com.mchange.v2.resourcepool.BasicResourcePool@14d1d41
    [managed: 0, unused: 0
    , excluded: 0] (e.g.
    com.mchange.v2.c3p0.impl.NewPooledConnection@1ae90c)
    2006-08-07 17:25:36,228 [Timer-0] DEBUG - Checking for
    expired resources - Mon Aug 07 17:25:36 EST 2006
    [com.mchange.v2.resourcepool.BasicResour
    cePool@14d1d41]
    2006-08-07 17:25:37,332 [DeliveryReceiptJMSConsumer4]
    DEBUG - awaitAvailable():
    com.mchange.v2.c3p0.impl.NewPooledConnection@1ae90c
    2006-08-07 17:25:37,333 [DeliveryReceiptJMSConsumer4]
    DEBUG - trace
    com.mchange.v2.resourcepool.BasicResourcePool@14d1d41
    [managed: 0, unused: 0
    , excluded: 0] (e.g.
    com.mchange.v2.c3p0.impl.NewPooledConnection@1ae90c)
    2006-08-07 17:25:43,730 [Timer-0] DEBUG - Checking for
    expired resources - Mon Aug 07 17:25:43 EST 2006
    [com.mchange.v2.resourcepool.BasicResour
    cePool@14d1d41]
    2006-08-07 17:25:51,350 [Timer-0] DEBUG - Checking for
    expired resources - Mon Aug 07 17:25:51 EST 2006
    [com.mchange.v2.resourcepool.BasicResour
    cePool@14d1d41]

     
  • Logged In: NO

    I have tried using c3p0-0.9.0.3, and the problem still
    happens. Just like before, it only happens intermittently
    and is hard to reproduce.

     
  • Steve Waldman
    Steve Waldman
    2006-09-07

    Logged In: YES
    user_id=175530

    Any better in c3p0-0.9.1-preX? (Do give 0.9.1-pre7 a try...
    hot off the presses, and many fixes and improvements.)

     
  • Steve Waldman
    Steve Waldman
    2006-09-07

    • status: open --> closed