javaでのスレッドリークについて

システムについて知識が浅いため、必要な情報が足りない可能性もあります。
他に必要な情報があれば提示させていただきますのでご指摘ください。

前提・実現したいこと

java、spring mvc、apache poiを使用してwebアプリでExcel出力の処理を実装しています。
Excel出力を何度か行うとリクエストの応答がなくなります。
（画面は読み込み中となり、おそらくExcelの処理まで到達していない）

自分なりに調査した結果、スレッドリークしているのではないかと予想しています。
理由としましては、処理を度にスレッドダンプにwaitのログが吐かれていたため。

スレッドリークの場合、どいういった箇所に注意すればよいか、
また原因が違う場合はどういった対処が必要かを教えていただきたいです。

発生している問題・エラーメッセージ

現象が発生した際のtomcatのスレッドダンプとなります。
文字数制限のため、関係がありそうな箇所の抜粋となります。

2018-02-23 12:50:40
Full thread dump Java HotSpot(TM) 64-Bit Server VM (25.121-b13 mixed mode):

"ajp-nio-8009-exec-10" #36 daemon prio=5 os_prio=0 tid=0x000000001c096800 nid=0x1e7c waiting on condition [0x0000000028b2f000]
java.lang.Thread.State: WAITING (parking)
at sun.misc.Unsafe.park(Native Method)

parking to wait for <0x000000008e9bd420> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)

at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
at org.apache.tomcat.util.threads.TaskQueue.take(TaskQueue.java:103)
at org.apache.tomcat.util.threads.TaskQueue.take(TaskQueue.java:31)
at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1067)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1127)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
at java.lang.Thread.run(Thread.java:745)

"ajp-nio-8009-exec-9" #35 daemon prio=5 os_prio=0 tid=0x000000001c096000 nid=0x1a98 waiting on condition [0x0000000028a2f000]
java.lang.Thread.State: WAITING (parking)
at sun.misc.Unsafe.park(Native Method)

parking to wait for <0x000000008e9bd420> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)

at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
at org.apache.tomcat.util.threads.TaskQueue.take(TaskQueue.java:103)
at org.apache.tomcat.util.threads.TaskQueue.take(TaskQueue.java:31)
at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1067)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1127)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
at java.lang.Thread.run(Thread.java:745)

"ajp-nio-8009-exec-8" #34 daemon prio=5 os_prio=0 tid=0x000000001c095000 nid=0xf70 waiting on condition [0x000000002892f000]
java.lang.Thread.State: WAITING (parking)
at sun.misc.Unsafe.park(Native Method)

parking to wait for <0x000000008e9bd420> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)

at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
at org.apache.tomcat.util.threads.TaskQueue.take(TaskQueue.java:103)
at org.apache.tomcat.util.threads.TaskQueue.take(TaskQueue.java:31)
at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1067)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1127)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
at java.lang.Thread.run(Thread.java:745)

"ajp-nio-8009-exec-7" #33 daemon prio=5 os_prio=0 tid=0x000000001c091800 nid=0x10f8 waiting on condition [0x000000002882f000]
java.lang.Thread.State: WAITING (parking)
at sun.misc.Unsafe.park(Native Method)

parking to wait for <0x000000008e9bd420> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)

at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
at org.apache.tomcat.util.threads.TaskQueue.take(TaskQueue.java:103)
at org.apache.tomcat.util.threads.TaskQueue.take(TaskQueue.java:31)
at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1067)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1127)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
at java.lang.Thread.run(Thread.java:745)

＝＝＝＝＝＝＝＝＝＝＝＝＝＝＝＝＝＝＝＝＝＝＝＝＝＝＝＝＝＝
■■■以下がtomcatのログです。■■■

[2018-02-23 17:04:44,731] [ERROR] localhost-startStop-2 org.apache.catalina.loader.WebappClassLoaderBase - The web application [XXX] created a ThreadLocal with key of type [com.microsoft.sqlserver.jdbc.ActivityCorrelator$1] (value [com.microsoft.sqlserver.jdbc.ActivityCorrelator$1@43b494c4]) and a value of type [com.microsoft.sqlserver.jdbc.ActivityId] (value [06408c05-b19c-4b0b-b710-17f80bc9dfde-43]) but failed to remove it when the web application was stopped. Threads are going to be renewed over time to try and avoid a probable memory leak.
[2018-02-23 17:04:44,731] [ERROR] localhost-startStop-2 org.apache.catalina.loader.WebappClassLoaderBase - The web application [XXX] created a ThreadLocal with key of type [com.microsoft.sqlserver.jdbc.ActivityCorrelator$1] (value [com.microsoft.sqlserver.jdbc.ActivityCorrelator$1@43b494c4]) and a value of type [com.microsoft.sqlserver.jdbc.ActivityId] (value [06408c05-b19c-4b0b-b710-17f80bc9dfde-43]) but failed to remove it when the web application was stopped. Threads are going to be renewed over time to try and avoid a probable memory leak.
[2018-02-23 17:04:44,732] [ERROR] localhost-startStop-2 org.apache.catalina.loader.WebappClassLoaderBase - The web application [XXX] created a ThreadLocal with key of type [com.microsoft.sqlserver.jdbc.ActivityCorrelator$1] (value [com.microsoft.sqlserver.jdbc.ActivityCorrelator$1@43b494c4]) and a value of type [com.microsoft.sqlserver.jdbc.ActivityId] (value [c3609dbd-95ec-45d0-9695-c5c3f2624883-17]) but failed to remove it when the web application was stopped. Threads are going to be renewed over time to try and avoid a probable memory leak.
[2018-02-23 17:04:44,732] [ERROR] localhost-startStop-2 org.apache.catalina.loader.WebappClassLoaderBase - The web application [XXX] created a ThreadLocal with key of type [com.microsoft.sqlserver.jdbc.ActivityCorrelator$1] (value [com.microsoft.sqlserver.jdbc.ActivityCorrelator$1@43b494c4]) and a value of type [com.microsoft.sqlserver.jdbc.ActivityId] (value [c3609dbd-95ec-45d0-9695-c5c3f2624883-17]) but failed to remove it when the web application was stopped. Threads are going to be renewed over time to try and avoid a probable memory leak.

該当のソースコード

java,spring mvc

ソースコードは現在手元になく、提示できません。

スレッドに関係しそうな処理としては、以下のような処理ですが、処理の中でマルチスレッドにはしていません。
while (条件式){
Thread.sleep(3000)
}

試したこと

特になし。

補足情報（FW/ツールのバージョンなど）

Java 8 Update 121
Apache2.4.29
Tomcat8.0.36
(組み込みtomcatではありません)
spring framework 4.3.6
spring mvcを使用。spring bootではありません。

退会済みユーザー

2018/02/24 08:26

Springbootや組み込みTomcatサーバーじゃないてことでいいのよね?

MasterPanna

2018/02/24 09:17 編集

spring bootはありません。 tomcatサーバーじゃない、というのはtomcatでwebサーバーの機能も使用しているという意味でしょうか？ webサーバーはapacheを使用しています。答えになっていますでしょうか。

退会済みユーザー

2018/02/24 09:22

「（サーバー版）TOMCATサーバー」ではなく「組み込みTOMCATサーバー」かということだが、その分だとを使ってないで確定だね

MasterPanna

2018/02/24 10:06

おそらく違うと思います。

行動規範の内容に同意します

回答1件

ベストアンサー

apache poiを使用してwebアプリでExcel出力の処理を実装しています。

とのことですが、apache poiはかなりメモリを食うみたいですが、
tomcatに割り当ててるメモリは十分ですか。
また大きいファイルを出力しようとしていませんか。

スレッドダンプからスレッドが滞留しているようなので、
ご提示のソースのwhile文を抜けれていないスレッドが滞留しているのだと思います。
スレッドダンプはlocalhostのようですが、ソースを修正して実行することはできますか。
whileの中と終わった時にlogを仕込めば、どのくらい滞留しているか確認することができます。

apache poiがメモリの使い過ぎで、GCが頻発しているのではないかと思うので、
ログだけ見て判断するのは無理です。

以下は、メモリーリークなどボクが疑う時の確認することです。

apache（webサーバ）のaccess.logを確認。

apacheがちゃんとリクエスト受けれてるよね、くらいの確認です。
意図してないrequestが沢山流れているのであれば、
クライアント側を疑います。

jstat -gcutilでtomcatのヒープ/GCの確認。

メモリーリークしていると、この辺りで分かるかもしれません。
あまり頻繁にGCが起きてたり、GC起きたのにメモリが解放されない場合、
メモリーリークを疑います。

ヒープダンプの取得

ボクはここまではあまり行わないので、詳しくはググってください。
開発環境で動かしながら確かめたほうが早いです。

投稿2018/02/26 04:10

szk.

総合スコア1400

MasterPanna

2018/03/01 11:14

ご丁寧な回答ありがとうございます。とても参考になりました。 >apache（webサーバ）のaccess.logを確認。 >apacheがちゃんとリクエスト受けれてるよね、くらいの確認です。 accessログを確認しましたところ、apacheまで行けてないようでした。初歩的な確認漏れでお恥ずかしいです。 apacheのエラーログから内容を検索し、解決策がわかりました。 IEで多量にアクセスした場合のみ発生するエラーのようです。 apacheの設定を変更してから現象が発生しなくなりました。ご参考まで。 https://ah-2.com/2015/07/30/apache_win_not_respond.html

行動規範の内容に同意します