1. ホーム
  2. 質問と答え
  3. Tomcatのアクティブなスレッドがサーバーを積み重ねてサーバーを停止します

Tomcatのアクティブなスレッドがサーバーを積み重ねてサーバーを停止します

2012-04-07 10 views
3

DBとしてMySQLを使用するSpring-JPA-Hibernateアプリケーションを実行している運用サーバー（apache-tomcat-7.0.6）でこの問題が発生しています。この問題が発生すると、サーバーは遅くなり、1分以内に応答しなくなり、アクティブなtomcatスレッドの数が200になります（私たちはjavamelodyを使ってこれらのことを観察します）。 ログは次のようになり：Tomcatのアクティブなスレッドがサーバーを積み重ねてサーバーを停止します

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 [[email protected]] 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 [[email protected]] 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 [[email protected]] 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 [[email protected]] 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 [[email protected]] 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 [[email protected]] 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 [[email protected]] 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 [[email protected]] 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 [[email protected]] 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 [[email protected]] 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接続をチェックし、カウントは最大接続制限よりはるかに小さかった。

私はスレッドダンプも取っていましたが、そのような重いスレッドやスレッドを正確に指すことができるかどうかはわかりません。

さらにこの問題をデバッグするためのアイデアは、大歓迎です。

出典

2012-04-07 ThinkFloyd

+0

「同期してはいけないこと」があるようです。 – EJP

答えて

2

[OK]を、スレッドダンプを分析した後、我々は何らかの形で多くのスレッドが我々のアプリケーションでDB接続を管理C3P0ライブラリのawaitAvailable（）メソッドに待っていたことに気づいたので、 。プールの中で多くの同時接続がチェックアウトされ、チェックイン後に接続カウンタの値が膨大になった場合、古いライブラリにこの問題があったため、c3p0ライブラリ（0.9.1.2から0.9.2へ）をアップグレードするよう提案したディスカッションが見つかりました。新しい接続をチェックアウトすることができず、プロセスが接続を永続的に待つ結果になります（チェックアウトタイムアウト= 0）。

しかし、我々は、我々は接続に何が起こっているか確認するためにdebugUnreturnedConnectionStackTracesにプロパティを使用して、この問題に直面し、彼らが利用できない理由をしていても、ライブラリをアップグレードした後。 1日のログの後、私たちは、DB接続を漏らしていたコードがc3p0によって管理されていることを認識しました。 finallyブロックでエンティティマネージャを閉じる前にcatchブロックでrollback（）を特に呼び出さなかったコードではフローがほとんどなかったため、例外の場合は接続がプールに戻らず、例外の頻度が高い（サイズタイムアウト間隔内のプールの数）、他のすべてのプロセススレッドが積み重なって接続を取得します。

このコードは固定されているため、このようなスレッドの重なりの問題は発生していません。

出典

2012-07-04 18:09:47 ThinkFloyd

2

ここではスレッドダンプ解析が進んでいます。この質問への答えは、あなたが根本的な原因を見つける必要があります。Thread Dump Analysis Tool/Method

出典

2012-04-07 09:43:58 samlewis

+0

提案してくれてありがとう、スレッドダンプが大いに役立った！答えを確認してください。 – ThinkFloyd

関連する問題

 関連する問題