[anirelles]

Hi,

there is something I would like to understand with Hibernate. I have these debg logs :

Quote

INFO: 21:04:36,448 DEBUG JDBCTransaction:54 - begin
INFO: 21:04:36,449 DEBUG BasicResourcePool:1644 - trace com.mchange.v2.resourcepool.BasicResourcePool@6f76dd71 [managed: 5, unused: 4, excluded: 0] (e.g. com.mchange.v2.c3p0.impl.NewPooledConnection@5511e6b9)
INFO: 21:04:36,450 DEBUG JDBCTransaction:59 - current autocommit status: true
INFO: 21:04:36,451 DEBUG JDBCTransaction:62 - disabling autocommit
...
SQL queries
...
INFO: 21:04:36,575 DEBUG JDBCTransaction:103 - commit
INFO: 21:04:36,576 DEBUG JDBCTransaction:193 - re-enabling autocommit
INFO: 21:04:36,577 DEBUG JDBCTransaction:116 - committed JDBC Connection

I am trying to understand how sessions to the database works, I have started by posting a question here : http://stackoverflow...atement-pooling
and from what I can read create a network connection to a database server is expensive, so I decide to use a connection pooling with c3p0, you can see it in the logs :

Quote

INFO: 21:04:36,449 DEBUG BasicResourcePool:1644 - trace com.mchange.v2.resourcepool.BasicResourcePool@6f76dd71 [managed: 5, unused: 4, excluded: 0] (e.g. com.mchange.v2.c3p0.impl.NewPooledConnection@5511e6b9)

My question is : does this log INFO: 21:04:36,448 DEBUG JDBCTransaction:54 - begin means that a session is created? Or transaction and session are 2 different things and c3p0 is working correctly ?

This post has been edited by anirelles: 19 January 2009 - 02:47 PM

[anirelles]

ok
I analyzed the debug logs of my application and I can see this when I start it :

Quote

INFO: 23:45:13,059 DEBUG BasicResourcePool:404 - incremented pending_acquires: 1
INFO: 23:45:13,060 DEBUG BasicResourcePool:404 - incremented pending_acquires: 2
INFO: 23:45:13,061 DEBUG BasicResourcePool:404 - incremented pending_acquires: 3
INFO: 23:45:13,062 DEBUG BasicResourcePool:404 - incremented pending_acquires: 4
INFO: 23:45:13,063 DEBUG BasicResourcePool:404 - incremented pending_acquires: 5
INFO: 23:45:13,075 DEBUG BasicResourcePool:289 - com.mchange.v2.resourcepool.BasicResourcePool@6342f024 config: [start -> 3; min -> 5; max -> 50; inc -> 1; num_acq_attempts -> 30; acq_attempt_delay -> 1000; check_idle_resources_delay -> 0; mox_resource_age -> 0; max_idle_time -> 0; excess_max_idle_time -> 0; destroy_unreturned_resc_time -> 0; expiration_enforcement_delay -> 0; break_on_acquisition_failure -> false; debug_store_checkout_exceptions -> false]
INFO: 23:45:13,079 INFO AbstractPoolBackedDataSource:462 - Initializing c3p0 pool... com.mchange.v2.c3p0.ComboPooledDataSource [ acquireIncrement -> 1, acquireRetryAttempts -> 30, acquireRetryDelay -> 1000, autoCommitOnClose -> false, automaticTestTable -> null, breakAfterAcquireFailure -> false, checkoutTimeout -> 0, connectionCustomizerClassName -> null, connectionTesterClassName -> com.mchange.v2.c3p0.impl.DefaultConnectionTester, dataSourceName -> z8kfsx7y1wbesehm58j4v|6b59cf26, debugUnreturnedConnectionStackTraces -> false, description -> null, driverClass -> com.mysql.jdbc.Driver, factoryClassLocation -> null, forceIgnoreUnresolvedTransactions -> false, identityToken -> z8kfsx7y1wbesehm58j4v|6b59cf26, idleConnectionTestPeriod -> 0, initialPoolSize -> 3, jdbcUrl -> jdbc:mysql://localhost/easytc, maxAdministrativeTaskTime -> 0, maxConnectionAge -> 0, maxIdleTime -> 0, maxIdleTimeExcessConnections -> 0, maxPoolSize -> 50, maxStatements -> 0, maxStatementsPerConnection -> 0, minPoolSize -> 5, numHelperThreads -> 3, numThreadsAwaitingCheckoutDefaultUser -> 0, preferredTestQuery -> null, properties -> {user=******, password=******}, propertyCycle -> 0, testConnectionOnCheckin -> false, testConnectionOnCheckout -> false, unreturnedConnectionTimeout -> 0, usesTraditionalReflectiveProxies -> false ]
INFO: 23:45:13,080 DEBUG BasicResourcePool:538 - acquire test -- pool size: 0; target_pool_size: 5; desired target? 1
INFO: 23:45:13,080 DEBUG BasicResourcePool:1291 - awaitAvailable(): [unknown]
INFO: 23:45:13,090 DEBUG BasicResourcePool:1644 - trace com.mchange.v2.resourcepool.BasicResourcePool@6342f024 [managed: 0, unused: 0, excluded: 0]
INFO: 23:45:13,241 DEBUG C3P0PooledConnectionPool:217 - com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool$1PooledConnectionResourcePoolManager@40ca6f53.acquireResource() returning.
INFO: 23:45:13,241 DEBUG C3P0PooledConnectionPool:217 - com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool$1PooledConnectionResourcePoolManager@40ca6f53.acquireResource() returning.
INFO: 23:45:13,241 DEBUG C3P0PooledConnectionPool:217 - com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool$1PooledConnectionResourcePoolManager@40ca6f53.acquireResource() returning.
INFO: 23:45:13,246 DEBUG BasicResourcePool:1644 - trace com.mchange.v2.resourcepool.BasicResourcePool@6342f024 [managed: 1, unused: 1, excluded: 0]
INFO: 23:45:13,247 DEBUG BasicResourcePool:422 - decremented pending_acquires: 4
INFO: 23:45:13,247 DEBUG BasicResourcePool:1644 - trace com.mchange.v2.resourcepool.BasicResourcePool@6342f024 [managed: 1, unused: 0, excluded: 0] (e.g. com.mchange.v2.c3p0.impl.NewPooledConnection@59377ac0)
INFO: 23:45:13,248 DEBUG BasicResourcePool:1644 - trace com.mchange.v2.resourcepool.BasicResourcePool@6342f024 [managed: 2, unused: 1, excluded: 0] (e.g. com.mchange.v2.c3p0.impl.NewPooledConnection@59377ac0)
INFO: 23:45:13,248 DEBUG BasicResourcePool:422 - decremented pending_acquires: 3
INFO: 23:45:13,255 INFO SettingsFactory:89 - RDBMS: MySQL, version: 5.0.51a
INFO: 23:45:13,256 INFO SettingsFactory:90 - JDBC driver: MySQL-AB JDBC Driver, version: mysql-connector-java-5.1.6 ( Revision: ${svn.Revision} )
INFO: 23:45:13,256 DEBUG C3P0PooledConnectionPool:217 - com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool$1PooledConnectionResourcePoolManager@40ca6f53.acquireResource() returning.
INFO: 23:45:13,256 DEBUG BasicResourcePool:1644 - trace com.mchange.v2.resourcepool.BasicResourcePool@6342f024 [managed: 3, unused: 2, excluded: 0] (e.g. com.mchange.v2.c3p0.impl.NewPooledConnection@59377ac0)
INFO: 23:45:13,258 DEBUG BasicResourcePool:422 - decremented pending_acquires: 2
INFO: 23:45:13,258 DEBUG BasicResourcePool:1644 - trace com.mchange.v2.resourcepool.BasicResourcePool@6342f024 [managed: 4, unused: 3, excluded: 0] (e.g. com.mchange.v2.c3p0.impl.NewPooledConnection@59377ac0)
INFO: 23:45:13,258 DEBUG BasicResourcePool:422 - decremented pending_acquires: 1
INFO: 23:45:13,260 DEBUG BasicResourcePool:1644 - trace com.mchange.v2.resourcepool.BasicResourcePool@6342f024 [managed: 4, unused: 3, excluded: 0] (e.g. com.mchange.v2.c3p0.impl.NewPooledConnection@59377ac0)
INFO: 23:45:13,261 DEBUG NewProxyConnection:1260 - com.mchange.v2.c3p0.impl.NewProxyConnection@18317b1d: close() called more than once.
INFO: 23:45:13,262 DEBUG C3P0PooledConnectionPool:217 - com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool$1PooledConnectionResourcePoolManager@40ca6f53.acquireResource() returning.
INFO: 23:45:13,263 DEBUG BasicResourcePool:1644 - trace com.mchange.v2.resourcepool.BasicResourcePool@6342f024 [managed: 5, unused: 5, excluded: 0] (e.g. com.mchange.v2.c3p0.impl.NewPooledConnection@59377ac0)
INFO: 23:45:13,263 DEBUG BasicResourcePool:422 - decremented pending_acquires: 0

It seems c3p0 aquire 5 connection resource from the databse, I think they are the sessions with an expensive cost.

In the logs I saw this too ; INFO: 23:45:07,971 INFO SettingsFactory:147 - Automatic session close at end of transaction: disabled

So now I'm pretty sure that the sessiosn aren't close at the end of a JDBC transaction. Now I would like to know if a JDBC transaction is expensive

[anirelles]

yeah they are expensive if you do a commit after each statement

I found this site that answered all my question :

Best practices to improve performance in JDBC
http://www.preciseja...f/j2ee/JDBC.htm