Tomcat 활성 스레드가 쌓여서 서버가 작동을 멈춤

Question

DB로 MySQL을 사용하는 Spring-JPA-Hibernate 애플리케이션을 실행중인 프로덕션 서버 (apache-tomcat-7.0.6)에서이 문제가 발생했습니다. 이 문제가 발생하는 동안 서버는 느려지고 1 분 안에 활성 tomcat 스레드 수가 200 개 (웹에서 javamelody를 사용)까지 응답하지 않게됩니다. 로그는 같은 모양 :

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' 

와 서버가 200 개 스레드 (1-2 분 소요)에 도달하고 응답하지 않을 때까지 트랜잭션이 생성이 일어나고에 유지합니다. 이 시간 동안 MySQL 연결을 점검하고 최대 연결 제한보다 훨씬 적습니다.

우리는 스레드 덤프도 가져 왔지만 정확히 무엇이 그 더미 나 스레드를 가리킬 수 있는지 잘 모르겠습니다.

이 문제를 디버그하는 데 도움이되는 아이디어가 있다면 언제든지 환영합니다.

Answer 1

좋아, 스레드 덤프를 분석 한 후 우리는 어떻게 든 많은 스레드는 우리의 응용 프로그램에서 DB 연결을 관리 C3P0 라이브러리의 awaitAvailable() 메소드에 기다리는 것을 깨달았다 그래서 . 누군가가 c3p0 라이브러리 (0.9.1.2에서 0.9.2로)를 업그레이드하겠다고 제안한 토론을 발견했습니다. 왜냐하면 오래된 라이브러리에 많은 동시 연결이 풀에서 체크 아웃되고 연결 카운터 값이 체크인 후 부풀려져서 새로운 연결을 체크 아웃 할 수 없으며 프로세스가 연결을 끊임없이 기다릴 수 있습니다 (우리는 checkout timeout = 0을가집니다).

라이브러리를 업그레이드 한 후에도 우리는이 문제가 발생하여 debugUnreturnedConnectionStackTraces 속성을 사용하여 연결에 어떤 현상이 발생했는지 확인할 수없는 이유를 확인했습니다. 하루의 로그 후에 우리는 DB 연결을 새어 나가는 코드가 c3p0에 의해 관리된다는 것을 깨달았습니다. finally 블록에서 엔티티 관리자를 닫기 전에 catch 블록에서 rollback()을 호출하지 않는 코드가 거의 없었기 때문에 예외가 발생하면 연결이 풀로 돌아 오지 않고 예외 빈도가 높습니다 (크기보다 큼 시간 초과 간격 내의 풀)을 사용하면 다른 모든 프로세스 스레드가 연결되어 연결됩니다.

이 코드는 고정되어 있으므로 이러한 스레드 더미 문제는 발생하지 않았습니다.

Answer 2

스레드 덤프 분석이 여기에 있습니다. 이 질문에 대한 대답은 근본 원인을 찾는 데 도움이 될 것입니다 Thread Dump Analysis Tool/Method