Tomcat active themes accumulate and stop server
We have this issue with our production servers (apache-tomcat-7.0.6) running a Spring-JPA-Hibernate application using MySQL as DB. During this issue, the server becomes slow and within a minute it becomes unresponsive, the number of active tomcat threads increases to 200 (we use javamelody to watch for these things). The logs look something like this:
2012-04-07 07:53:48,058 DEBUG AuthenticationHandler:("http-bio-7006"-exec-304):35 - Authentication handler : ~
2012-04-07 07:53:48,059 DEBUG AuthenticationHandler:("http-bio-7006"-exec-304):45 - Service Id : 1333765428059-/xxx-framework-service/platform/items/search/
2012-04-07 07:53:48,060 DEBUG DefaultListableBeanFactory:("http-bio-7006"-exec-304):242 - Returning cached instance of singleton bean 'transactionManager'
2012-04-07 07:53:48,060 DEBUG JpaTransactionManager:("http-bio-7006"-exec-304):365 - Creating new transaction with name [com.xxx.framework.manager.ItemManager.search]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT,readOnly; ''
2012-04-07 07:53:48,060 DEBUG JpaTransactionManager:("http-bio-7006"-exec-304):323 - Opened new EntityManager [org.hibernate.ejb.EntityManagerImpl@6aee43a9] for JPA transaction
2012-04-07 07:53:53,583 DEBUG AuthenticationHandler:("http-bio-7006"-exec-217):35 - Authentication handler : System~System
2012-04-07 07:53:53,584 DEBUG AuthenticationHandler:("http-bio-7006"-exec-217):45 - Service Id : 1333765433584-/xxx-framework-service/platform/skus/get_sku_details
2012-04-07 07:53:53,585 DEBUG DefaultListableBeanFactory:("http-bio-7006"-exec-217):242 - Returning cached instance of singleton bean 'transactionManager'
2012-04-07 07:53:53,586 DEBUG JpaTransactionManager:("http-bio-7006"-exec-217):365 - Creating new transaction with name [com.xxx.framework.manager.SkuServiceManager.getSkuDetails]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT; ''
2012-04-07 07:53:53,586 DEBUG JpaTransactionManager:("http-bio-7006"-exec-217):323 - Opened new EntityManager [org.hibernate.ejb.EntityManagerImpl@7cb3b78] for JPA transaction
2012-04-07 07:54:04,297 DEBUG AuthenticationHandler:("http-bio-7006"-exec-311):35 - Authentication handler : System~System
2012-04-07 07:54:04,298 DEBUG AuthenticationHandler:("http-bio-7006"-exec-311):45 - Service Id : 1333765444298-/xxx-framework-service/platform/skus/get_sku_details
2012-04-07 07:54:04,299 DEBUG DefaultListableBeanFactory:("http-bio-7006"-exec-311):242 - Returning cached instance of singleton bean 'transactionManager'
2012-04-07 07:54:04,299 DEBUG JpaTransactionManager:("http-bio-7006"-exec-311):365 - Creating new transaction with name [com.xxx.framework.manager.SkuServiceManager.getSkuDetails]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT; ''
2012-04-07 07:54:04,299 DEBUG JpaTransactionManager:("http-bio-7006"-exec-311):323 - Opened new EntityManager [org.hibernate.ejb.EntityManagerImpl@d8c7ec2] for JPA transaction
2012-04-07 07:54:05,713 DEBUG AuthenticationHandler:("http-bio-7006"-exec-252):35 - Authentication handler : System~System
2012-04-07 07:54:05,714 DEBUG AuthenticationHandler:("http-bio-7006"-exec-252):45 - Service Id : 1333765445714-/xxx-framework-service/platform/skus/get_sku_details
2012-04-07 07:54:05,715 DEBUG DefaultListableBeanFactory:("http-bio-7006"-exec-252):242 - Returning cached instance of singleton bean 'transactionManager'
2012-04-07 07:54:05,715 DEBUG JpaTransactionManager:("http-bio-7006"-exec-252):365 - Creating new transaction with name [com.xxx.framework.manager.SkuServiceManager.getSkuDetails]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT; ''
2012-04-07 07:54:05,715 DEBUG JpaTransactionManager:("http-bio-7006"-exec-252):323 - Opened new EntityManager [org.hibernate.ejb.EntityManagerImpl@685eb738] for JPA transaction
2012-04-07 07:54:16,293 DEBUG AuthenticationHandler:("http-bio-7006"-exec-282):35 - Authentication handler : System~System
2012-04-07 07:54:16,294 DEBUG AuthenticationHandler:("http-bio-7006"-exec-282):45 - Service Id : 1333765456294-/xxx-framework-service/platform/skus/get_sku_details
2012-04-07 07:54:16,295 DEBUG DefaultListableBeanFactory:("http-bio-7006"-exec-282):242 - Returning cached instance of singleton bean 'transactionManager'
2012-04-07 07:54:16,295 DEBUG JpaTransactionManager:("http-bio-7006"-exec-282):365 - Creating new transaction with name [com.xxx.framework.manager.SkuServiceManager.getSkuDetails]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT; ''
2012-04-07 07:54:16,296 DEBUG JpaTransactionManager:("http-bio-7006"-exec-282):323 - Opened new EntityManager [org.hibernate.ejb.EntityManagerImpl@6d37b108] for JPA transaction
2012-04-07 07:54:16,541 DEBUG AuthenticationHandler:("http-bio-7006"-exec-302):35 - Authentication handler : Heartbeat User~dummy_heartbeat
2012-04-07 07:54:16,542 DEBUG AuthenticationHandler:("http-bio-7006"-exec-302):45 - Service Id : 1333765456542-/xxx-framework-service/platform/skus/5500
2012-04-07 07:54:16,543 DEBUG DefaultListableBeanFactory:("http-bio-7006"-exec-302):242 - Returning cached instance of singleton bean 'transactionManager'
2012-04-07 07:54:16,543 DEBUG JpaTransactionManager:("http-bio-7006"-exec-302):365 - Creating new transaction with name [com.xxx.framework.manager.SkuServiceManager.findById]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT,readOnly; ''
2012-04-07 07:54:16,543 DEBUG JpaTransactionManager:("http-bio-7006"-exec-302):323 - Opened new EntityManager [org.hibernate.ejb.EntityManagerImpl@7a973a0f] for JPA transaction
2012-04-07 07:54:19,708 DEBUG AuthenticationHandler:("http-bio-7006"-exec-236):35 - Authentication handler : System~System
2012-04-07 07:54:19,709 DEBUG AuthenticationHandler:("http-bio-7006"-exec-236):45 - Service Id : 1333765459709-/xxx-framework-service/platform/skus/get_sku_details
2012-04-07 07:54:19,710 DEBUG DefaultListableBeanFactory:("http-bio-7006"-exec-236):242 - Returning cached instance of singleton bean 'transactionManager'
2012-04-07 07:54:19,710 DEBUG JpaTransactionManager:("http-bio-7006"-exec-236):365 - Creating new transaction with name [com.xxx.framework.manager.SkuServiceManager.getSkuDetails]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT; ''
2012-04-07 07:54:19,711 DEBUG JpaTransactionManager:("http-bio-7006"-exec-236):323 - Opened new EntityManager [org.hibernate.ejb.EntityManagerImpl@342f22a9] for JPA transaction
2012-04-07 07:54:22,648 DEBUG AuthenticationHandler:("http-bio-7006"-exec-292):35 - Authentication handler : System~System
2012-04-07 07:54:22,649 DEBUG AuthenticationHandler:("http-bio-7006"-exec-292):45 - Service Id : 1333765462649-/xxx-framework-service/platform/skus/get_avaliable_count
2012-04-07 07:54:22,650 DEBUG DefaultListableBeanFactory:("http-bio-7006"-exec-292):242 - Returning cached instance of singleton bean 'transactionManager'
2012-04-07 07:54:22,650 DEBUG JpaTransactionManager:("http-bio-7006"-exec-292):365 - Creating new transaction with name [com.xxx.framework.manager.SkuServiceManager.getAvaliableCountOpt]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT; ''
2012-04-07 07:54:22,650 DEBUG JpaTransactionManager:("http-bio-7006"-exec-292):323 - Opened new EntityManager [org.hibernate.ejb.EntityManagerImpl@5e5d2643] for JPA transaction
2012-04-07 07:54:25,751 DEBUG AuthenticationHandler:("http-bio-7006"-exec-291):35 - Authentication handler : System~System
2012-04-07 07:54:25,752 DEBUG AuthenticationHandler:("http-bio-7006"-exec-291):45 - Service Id : 1333765465752-/xxx-framework-service/platform/skus/get_sku_details
2012-04-07 07:54:25,753 DEBUG DefaultListableBeanFactory:("http-bio-7006"-exec-291):242 - Returning cached instance of singleton bean 'transactionManager'
2012-04-07 07:54:25,753 DEBUG JpaTransactionManager:("http-bio-7006"-exec-291):365 - Creating new transaction with name [com.xxx.framework.manager.SkuServiceManager.getSkuDetails]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT; ''
2012-04-07 07:54:25,754 DEBUG JpaTransactionManager:("http-bio-7006"-exec-291):323 - Opened new EntityManager [org.hibernate.ejb.EntityManagerImpl@28c7c70b] for JPA transaction
2012-04-07 07:54:30,811 DEBUG AuthenticationHandler:("http-bio-7006"-exec-234):35 - Authentication handler : System~System
2012-04-07 07:54:30,812 DEBUG AuthenticationHandler:("http-bio-7006"-exec-234):45 - Service Id : 1333765470812-/xxx-framework-service/platform/skus/get_avaliable_count
2012-04-07 07:54:30,813 DEBUG DefaultListableBeanFactory:("http-bio-7006"-exec-234):242 - Returning cached instance of singleton bean 'transactionManager'
2012-04-07 07:54:30,814 DEBUG JpaTransactionManager:("http-bio-7006"-exec-234):365 - Creating new transaction with name [com.xxx.framework.manager.SkuServiceManager.getAvaliableCountOpt]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT; ''
2012-04-07 07:54:30,814 DEBUG JpaTransactionManager:("http-bio-7006"-exec-234):323 - Opened new EntityManager [org.hibernate.ejb.EntityManagerImpl@140768d6] for JPA transaction
2012-04-07 07:54:33,790 DEBUG AuthenticationHandler:("http-bio-7006"-exec-301):35 - Authentication handler : System~System
2012-04-07 07:54:33,790 DEBUG AuthenticationHandler:("http-bio-7006"-exec-301):45 - Service Id : 1333765473790-/xxx-framework-service/platform/skus/get_sku_details
2012-04-07 07:54:33,792 DEBUG DefaultListableBeanFactory:("http-bio-7006"-exec-301):242 - Returning cached instance of singleton bean 'transactionManager'
and this transaction creation continues until the server reaches 200 threads (takes 1-2 minutes) and stops responding. I checked MySQL connections during this time and the count was much less than the maximum connection limit.
We also used a stream dump, but I'm not sure what exactly would point to such a heap or streams.
Any ideas for further debugging this issue are appreciated.
+3
source to share
2 answers
So, after analyzing the thread dump, we realized that somehow many threads were waiting in the awaitAvailable () method of the c3p0 library that manages the DB connections in our application. We found a discussion where someone suggested updating the c3p0 library (from 0.9.1.2 to 0.9.2) because the old library had this problem, when a lot of concurrent connections were pulled from the pool, the connection counter value remains bloated after registering and, hence does not allow checking for new connections and causes processes to wait for connections constantly (we had checkout timeout = 0).
But even after updating the library, we ran into this problem, so we used the debugUnreturnedConnectionStackTraces property to see what happens to the connections and why they are not available. After a day of logging, we realized that our code that flows through DB connections is being controlled by c3p0. There were few threads in our code in which we did not call rollback () specifically in the catch block before closing the Manager object in the finally block, so in case of exceptions, the connection was not returned to the pool and if the exception rate is high (greater than the pool size in the timeout interval ), then all other process threads will accumulate to get the connection.
Since this code has been fixed, we have not seen such thread overlay issues.
+2
source to share
Stream dump analysis is the way forward. The answers to this question will help you find the root cause: Thread dump analysis tool / method
+2
source to share