Hello About using useEquals="false" property I guess we defined when we started using this pool. After reading the documentation i guess it is better to leave it out (it has no effect on the test - i tested it).
We dont have long running queries because there is not much data and all operations are fast (the longest one are ranging from 1 to 2 seconds: i used slowqueryinterceptor and sql server profiler). The test always starts with empty database. I never got any abandoned messages in the stdout or catalina.out (logabandoned set to true) - I put everything that is not from our application and is at least on INFO level to catalina.out. I added org.apache.tomcat.jdbc.pool package to logs on TRACE level and the only line that is repeating (5 times) is: 2013-11-19 15:25:24,764 DEBUG [main] org.apache.tomcat.jdbc.pool.PooledConnection connectUsingDriver(): Instantiating driver using class: com.microsoft.sqlserver.jdbc.SQLServerDriver [url=jdbc:sqlserver://*****;databaseName=chiTestDB] Dont know if there is really that little logging in connection pool. In that case debugging looks like the only option? About C3P0 pool:we are under the impression that org.apache.tomcat.jdbc.pool is the only way to go (production quality) after reading The Tomcat JDBC Connection Pool page (after your comment i guess this is not true and commons-dbcp is production quality alternative?). So since this did not work for us we started looking for alternative and C3P0 pooped up in connection pool comparisons or in some stackoverflow thread. regards, Marko On Mon, Nov 18, 2013 at 11:03 PM, Christopher Schultz < ch...@christopherschultz.net> wrote: > -----BEGIN PGP SIGNED MESSAGE----- > Hash: SHA256 > > Marko, > > On 11/18/13, 3:48 AM, marko lugarič wrote: > > We have received an issue from our customer that after some time in > > production they get empty connection pool. After some time we > > managed to reproduce their problem in our test environment with > > smaller number of pool connections. > > > > So generally we have a problem that if connection pool is under > > heavy load (meaning most of the time all the connections are taken > > - active) it starts to loose database connections (we call it > > bleed): they are lost from the perspective of Tomcat but they are > > very much alive when we check then on the database side. > > > > We are using Apache Tomcat 7.0.47 running on java 1.6. Database is > > SQL Server 2008R2 and we are using Hibernate as persistence > > provider. Our configuration is defined in server.xml in the > > GlobalNamingResources section (referenced from context.xml): > > > > <Resource name="jdbc/ChiDS" auth="Container" > > type="javax.sql.DataSource" > > factory="org.apache.tomcat.jdbc.pool.DataSourceFactory" > > driverClassName="com.microsoft.sqlserver.jdbc.SQLServerDriver" > > url="jdbc:sqlserver://*****;databaseName=chiTestDB" > > username="*****" password="*****" initialSize="2" maxActive="5" > > maxIdle="4" minIdle="2" maxWait="15000" > > timeBetweenEvictionRunsMillis="30000" testOnBorrow="true" > > testOnReturn="false" testOnIdle="false" validationQuery="SELECT 1" > > validationInterval="30000" removeAbandoned="true" > > removeAbandonedTimeout="60" useEquals="false"/> > > I'm just curious: why are you using useEquals="false" here? I've > wondered what the use-case is for this configuration attribute. > > > I will explain in detail what happens. For better understanding I > > am also providing graph of idle and active connections from Java > > VisualVM MBeans viewer: > > http://img11.imageshack.us/img11/6888/fm4j.jpg > > > > So we start the server and connect clients to the server that > > generate small database load. After that we order half of our > > clients to start generating operations that result in medium > > database load (I think around 300 transactions per second). We can > > see from the graph that connection pool is behaving normally > > (sometimes all 5 connections are taken, sometimes not - if we would > > run test like this all day everything would be OK). So after 7 > > minutes we increase the load by 100% (other half of clients start > > to do operations). > > > > The load is bigger than 5 pool connections can handle: pretty much > > all the time all 5 connections are active so we can soon expect > > that server application logic will start to receive exceptions that > > jdbc connection is not available (this should happen if application > > logic does not receive pool connection in 15 seconds). Indeed this > > happens and the following exception is thrown: > > > > Caused by: org.hibernate.exception.GenericJDBCException: Cannot > > open connection at > > > org.hibernate.exception.SQLStateConverter.handledNonSpecificException(SQLStateConverter.java:140) > > > > > at > > > org.hibernate.exception.SQLStateConverter.convert(SQLStateConverter.java:128) > > > > > at > > > org.hibernate.exception.JDBCExceptionHelper.convert(JDBCExceptionHelper.java:66) > > > > > at > > > org.hibernate.exception.JDBCExceptionHelper.convert(JDBCExceptionHelper.java:52) > > > > > at > > > org.hibernate.jdbc.ConnectionManager.openConnection(ConnectionManager.java:449) > > > > > at > > > org.hibernate.jdbc.ConnectionManager.getConnection(ConnectionManager.java:167) > > > > > at org.hibernate.jdbc.JDBCContext.connection(JDBCContext.java:142) > > at > > org.hibernate.transaction.JDBCTransaction.begin(JDBCTransaction.java:85) > > > > > at > > org.hibernate.impl.SessionImpl.beginTransaction(SessionImpl.java:1463) > > > > > at org.hibernate.ejb.TransactionImpl.begin(TransactionImpl.java:60) > > ... 18 more Caused by: java.sql.SQLException: Pool wait > > interrupted. at > > > org.apache.tomcat.jdbc.pool.ConnectionPool.borrowConnection(ConnectionPool.java:655) > > > > > at > > > org.apache.tomcat.jdbc.pool.ConnectionPool.getConnection(ConnectionPool.java:188) > > > > > at > > > org.apache.tomcat.jdbc.pool.DataSourceProxy.getConnection(DataSourceProxy.java:128) > > > > > at > > > org.hibernate.connection.DatasourceConnectionProvider.getConnection(DatasourceConnectionProvider.java:92) > > > > > at > > > org.hibernate.jdbc.ConnectionManager.openConnection(ConnectionManager.java:446) > > > > > ... 23 more > > Caused by: java.lang.InterruptedException at > > > java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedNanos(AbstractQueuedSynchronizer.java:1024) > > > > > at > > > java.util.concurrent.locks.AbstractQueuedSynchronizer.tryAcquireSharedNanos(AbstractQueuedSynchronizer.java:1303) > > > > > at java.util.concurrent.CountDownLatch.await(CountDownLatch.java:253) > > at > > > org.apache.tomcat.jdbc.pool.FairBlockingQueue.poll(FairBlockingQueue.java:151) > > > > > at > > > org.apache.tomcat.jdbc.pool.ConnectionPool.borrowConnection(ConnectionPool.java:650) > > Good. > > > It seems like that is the appropriate result given the situation > you describe. > > > But here something goes wrong because active connections count > > drops by 1 and never goes back even though database load is still > > the same. Judging from the graph at this moment pool is giving only > > 4 pool connections to the application. Pretty soon the same > > exception is thrown again reducing the active pool count by 1. And > > then very quickly same exception is thrown 3 more times and pool > > has no active or idle connections. After this another type of > > exceptions starts to pop in log file: > > > > Caused by: javax.persistence.PersistenceException: > > org.hibernate.exception.GenericJDBCException: Cannot open > > connection at > > > org.hibernate.ejb.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1235) > > > > > at > > > org.hibernate.ejb.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1168) > > > > > at > > > org.hibernate.ejb.AbstractEntityManagerImpl.throwPersistenceException(AbstractEntityManagerImpl.java:1245) > > > > > at org.hibernate.ejb.TransactionImpl.begin(TransactionImpl.java:63) > > at > > com.hsl.chi.persistence.dao.jpa.DAO.beginEntityTransaction(DAO.java:1505) > > > > > at > > com.hsl.chi.persistence.dao.jpa.DAO.beginFirstSubOperation(DAO.java:992) > > > > > at > > > com.hsl.chi.persistence.dao.jpa.SequenceDAO.internalResetSequence(SequenceDAO.java:568) > > > > > ... 9 more > > Caused by: org.hibernate.exception.GenericJDBCException: Cannot > > open connection at > > > org.hibernate.exception.SQLStateConverter.handledNonSpecificException(SQLStateConverter.java:140) > > > > > at > > > org.hibernate.exception.SQLStateConverter.convert(SQLStateConverter.java:128) > > > > > at > > > org.hibernate.exception.JDBCExceptionHelper.convert(JDBCExceptionHelper.java:66) > > > > > at > > > org.hibernate.exception.JDBCExceptionHelper.convert(JDBCExceptionHelper.java:52) > > > > > at > > > org.hibernate.jdbc.ConnectionManager.openConnection(ConnectionManager.java:449) > > > > > at > > > org.hibernate.jdbc.ConnectionManager.getConnection(ConnectionManager.java:167) > > > > > at org.hibernate.jdbc.JDBCContext.connection(JDBCContext.java:142) > > at > > org.hibernate.transaction.JDBCTransaction.begin(JDBCTransaction.java:85) > > > > > at > > org.hibernate.impl.SessionImpl.beginTransaction(SessionImpl.java:1463) > > > > > at org.hibernate.ejb.TransactionImpl.begin(TransactionImpl.java:60) > > ... 12 more Caused by: > > org.apache.tomcat.jdbc.pool.PoolExhaustedException: > > [[ProtocolHandler]-[pool-1-thread-113]] Timeout: Pool empty. Unable > > to fetch a connection in 15 seconds, none available[size:5; busy:0; > > idle:0; lastwait:15000]. at > > > org.apache.tomcat.jdbc.pool.ConnectionPool.borrowConnection(ConnectionPool.java:674) > > > > > at > > > org.apache.tomcat.jdbc.pool.ConnectionPool.getConnection(ConnectionPool.java:188) > > > > > at > > > org.apache.tomcat.jdbc.pool.DataSourceProxy.getConnection(DataSourceProxy.java:128) > > > > > at > > > org.hibernate.connection.DatasourceConnectionProvider.getConnection(DatasourceConnectionProvider.java:92) > > > > > at > > > org.hibernate.jdbc.ConnectionManager.openConnection(ConnectionManager.java:446) > > > > So from the Tomcat point of view we have no jdbc connections to > > the database in the pool. From this point no database operation > > can succeed: even if load is reduced to minimum - every database > > operation fails from application. Then we check the database side: > > SQL server creates its internal process for each jdbc connection: > > we can see all 5 connections much alive doing nothing. > > > > Since we are using hibernate we were quickly able to do the same > > test on PostgreSQL database and identical scenario happens: > > PostgreSQL shows 5 idle processes while pool is empty. The only > > thing we can do here is to restart the Tomcat. > > > > We also tried other configurations (Tomcat 7.0.32, hibernate > > library was updated to latest version, we used PostgreSQL server > > instead of SQL server) and different connection pool properties but > > without any success - we always end up with empty pool. Tomcat > > properties that we tried: > > > > logAbandoned="true" - did not log anything (I guess stack trace > > should be thrown to console, log file if connection would not be > > closed from application?), so I guess hibernate is closing > > connections properly (we are always calling entity manager close > > method when we finish). > > Hibernate should be doing the right thing and always returning > connections to the pool. I think you can rely on that. However, if you > have long-running SQL queries, you might be hitting that abandoned > timeout. Are there any long-running queries in your transactions? > > You have timeBetweenEvictionRunsMillis set quite high: abandoned > connections won't be detected for maybe 30 seconds after they have > actually been abandoned. For your configuration, that may be 60 + 30 = > 90 seconds after the connection was last used that you will get any > kind of error in the logs. > > > jdbcInterceptors="StatementFinalizer;SlowQueryReportJmx(threshold=10000)" > > - statement finalizier did not help > > > > testOnReturn="true", testOnIdle="true", > > propagateInterruptState="true" - did not help > > > > > > So the last option was to change connection pool: we used C3P0 > > connection pool with properties that are similar in meaning as > > Tomcat ones. > > (How come everyone runs to C3P0 when things don't work in Tomcat!? > There are 2 pools available in Tomcat without having to download beta > software. Did you try commons-pool, which is currently the default pool?) > > > We repeated the above test case and it is working correctly. We > > have left it with full load half an hour in which we get a lot of > > exceptions that application did not receive connection but pool is > > still working OK (all connections are active almost all the time). > > Exception that is being thrown: > > com.mchange.v2.resourcepool.BasicResourcePool@437ff0 -- an attempt > > to checkout a resource was interrupted, and the pool is still live: > > some other thread must have either interrupted the Thread > > attempting checkout! java.lang.InterruptedException . Then we > > reduce the load and exceptions are soon gone since 5 connection can > > handle them. Here is the configuration from server.xml for C3P0: > > > > <Resource name="jdbc/ChiDS" auth="Container" > > type="com.mchange.v2.c3p0.ComboPooledDataSource" > > dataSourceName="jdbc/ChiDS" > > factory="org.apache.naming.factory.BeanFactory" > > driverClass="com.microsoft.sqlserver.jdbc.SQLServerDriver" > > jdbcUrl="jdbc:sqlserver://*****;databaseName=chiDB" user="*****" > > password="*****" initialPoolSize="2" minPoolSize="2" > > maxPoolSize="5" preferredTestQuery="SELECT 1" > > testConnectionOnCheckin="true" idleConnectionTestPeriod="30" > > numHelperThreads="5"/> > > > > Currently our customer raised maxActive to bigger number but i > > guess this will not do once they will start increasing the number > > of clients (our application has big amount of transactions) and > > they will have to change connection pool. Are there any additional > > configuration setting I can try on Tomcat connection pool, > > otherwise this looks like a bug? > > Can you confirm that, during your load tests, you never got any > "abandoned" messages on the console (stdout, catalina.out, etc.)? Have > you modified the logging configuration to eliminate such messages? > > I'm surprised that the pool is drying up without anything in the logs. > Can you raise the log level on the pool to DEBUG and re-run your load > test? > > - -chris > -----BEGIN PGP SIGNATURE----- > Version: GnuPG v1.4.15 (Darwin) > Comment: GPGTools - http://gpgtools.org > Comment: Using GnuPG with Thunderbird - http://www.enigmail.net/ > > iQIcBAEBCAAGBQJSio6kAAoJEBzwKT+lPKRYq0AQAKapJHdErG0qyP586EyVYpNG > Q25cBTvZskelDPL6FXBfh16p6ZfvrCnH7KYwxucoOv7RHw4F7tA4UEGMYx0q6hbv > VOho/NA5bDPE4fRHYN1Hif/uHIK8GlsNznFhJz91llxP8fLRykTtOZ2E6NKhztWK > M/qlW/DxAe/A1KAe46vO4XOzpzIa9dpfLhfGwh0J+n+efj+9ssVz52tmaHMso6tv > z4RLQcxVI/kDVSBE2y4p2kvZwhYKpHP7RTq9mhLK7U1SywfMdxNeMXAMy0E9jFRp > eukHfl4o4aUqtym1lYSWc/qPSO1svd2DGIUX6m/Z7X9t3V46gZIm0XXa2oEPO6am > AuUHS48Z9eyeJ0eOedq8qrfkxWFoIPwmJve4j3x7yXd6vGUKBnuIdqdLbH+AVoIW > fs/EN2uoupaLt9/U2XoeeQxIlHnAHAZeid+/5zssYyrjxNZrqMAHAIoIC6amZnN6 > WXncOPAG2ni8wIy0hESVpEggf2a4Lgbl7yg/R+akHxjyUCSjiyUo4+zH/5XrfyT5 > DfrvhVxpBpA6SPUCMjQKjTo41FO0Sb+bHe91qDQm7Ajp3ms7RTK4imn9O9ofOuVh > w9DBVC6oT/TgwSZToHqkPiAtwdHmltq8k9lC40gFJauL9seO1f3mu3XQiSfjfByL > 8GCc331YMkhDSmZDgIHB > =ZdwO > -----END PGP SIGNATURE----- > > --------------------------------------------------------------------- > To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org > For additional commands, e-mail: users-h...@tomcat.apache.org > >
