QA@IT

Javaプロセスが不定期にフリーズする

6457 PV

●環境

Redhat Linux 6.7
Oracle Java SE 1.8.0_60
spring framework 4.1.9
mybatis 3.3.1
logback 1.0.13

●内容

上記環境で1分毎に動作するアプリケーションを作成したのですが、
不定期にJavaプロセスがフリーズしてしまいます。
jstackによるスレッドダンプを採取しましたが、停止箇所はその時々で異なっていました。
ただし、すべてOSSの処理途中で停止しているようでした。

2つほどスレッドダンプの例を記載します。

【パターン1】logbackの処理の途中で停止しているパターン




"Abandoned connection cleanup thread" #21 daemon prio=5 os_prio=0 tid=0x00007f391c810800 nid=0x382b in Object.wait() [0x00007f38e46cb000]
java.lang.Thread.State: TIMED_WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:143)
-locked (a java.lang.ref.ReferenceQueue$Lock)
at com.mysql.jdbc.AbandonedConnectionCleanupThread.run(AbandonedConnectionCleanupThread.java:43)



"Finalizer" #3 daemon prio=8 os_prio=0 tid=0x00007f391c0a4800 nid=0x378a in Object.wait() [0x00007f38e6ae9000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:143)
-locked (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:164)
at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:209)

Locked ownable synchronizers:
-None

"Reference Handler" #2 daemon prio=10 os_prio=0 tid=0x00007f391c0a2800 nid=0x3789 in Object.wait() [0x00007f38e6bea000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
at java.lang.Object.wait(Object.java:502)
at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:157)
-locked (a java.lang.ref.Reference$Lock)

"main" #1 prio=5 os_prio=0 tid=0x00007f391c009000 nid=0x3755 runnable [0x00007f392221f000]
java.lang.Thread.State: RUNNABLE
at java.text.SimpleDateFormat.subFormat(SimpleDateFormat.java:1149)
at java.text.SimpleDateFormat.format(SimpleDateFormat.java:966)
at java.text.SimpleDateFormat.format(SimpleDateFormat.java:936)
at java.text.DateFormat.format(DateFormat.java:345)
at ch.qos.logback.core.util.CachingDateFormatter.format(CachingDateFormatter.java:49)
-locked (a ch.qos.logback.core.util.CachingDateFormatter)
at ch.qos.logback.classic.pattern.DateConverter.convert(DateConverter.java:63)
at ch.qos.logback.classic.pattern.DateConverter.convert(DateConverter.java:23)
at ch.qos.logback.core.pattern.FormattingConverter.write(FormattingConverter.java:37)
at ch.qos.logback.core.pattern.PatternLayoutBase.writeLoopOnConverters(PatternLayoutBase.java:119)
at ch.qos.logback.classic.PatternLayout.doLayout(PatternLayout.java:168)
at ch.qos.logback.classic.PatternLayout.doLayout(PatternLayout.java:59)
at ch.qos.logback.core.encoder.LayoutWrappingEncoder.doEncode(LayoutWrappingEncoder.java:134)
at ch.qos.logback.core.OutputStreamAppender.writeOut(OutputStreamAppender.java:188)
at ch.qos.logback.core.OutputStreamAppender.subAppend(OutputStreamAppender.java:212)
-locked (a ch.qos.logback.core.spi.LogbackLock)
at ch.qos.logback.core.OutputStreamAppender.append(OutputStreamAppender.java:103)
at ch.qos.logback.core.UnsynchronizedAppenderBase.doAppend(UnsynchronizedAppenderBase.java:88)
at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:48)
at ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:272)
at ch.qos.logback.classic.Logger.callAppenders(Logger.java:259)
at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:441)
at ch.qos.logback.classic.Logger.filterAndLog_0_Or3Plus(Logger.java:395)
at ch.qos.logback.classic.Logger.info(Logger.java:599)
at App1.main(App1.java:187) *// LOGGER.infoを実行している処理です。

Locked ownable synchronizers:
-None


【パターン2】spring frameworkのコンテキストの読み込みで停止しているパターン




"Finalizer" #3 daemon prio=8 os_prio=0 tid=0x00007f36e80a5000 nid=0x4e11 in Object.wait() [0x00007f36786d1000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
-waiting on (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:143)
-locked (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:164)
at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:209)

Locked ownable synchronizers:
-None

"Reference Handler" #2 daemon prio=10 os_prio=0 tid=0x00007f36e80a2800 nid=0x4df4 in Object.wait() [0x00007f36787d2000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
-waiting on (a java.lang.ref.Reference$Lock)
at java.lang.Object.wait(Object.java:502)
at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:157)
-locked (a java.lang.ref.Reference$Lock)

Locked ownable synchronizers:
-None

"main" #1 prio=5 os_prio=0 tid=0x00007f36e8009000 nid=0x4c89 runnable [0x00007f36ef766000]
java.lang.Thread.State: RUNNABLE
at org.springframework.asm.ClassReader.readMethod(ClassReader.java:1020)
at org.springframework.asm.ClassReader.accept(ClassReader.java:695)
at org.springframework.asm.ClassReader.accept(ClassReader.java:508)
at org.springframework.core.type.classreading.SimpleMetadataReader.(SimpleMetadataReader.java:64)
at org.springframework.core.type.classreading.SimpleMetadataReaderFactory.getMetadataReader(SimpleMetadataReaderFactory.java:98)
at org.springframework.core.type.classreading.CachingMetadataReaderFactory.getMetadataReader(CachingMetadataReaderFactory.java:102)
-locked (a org.springframework.core.type.classreading.CachingMetadataReaderFactory$1)
at org.springframework.core.type.classreading.SimpleMetadataReaderFactory.getMetadataReader(SimpleMetadataReaderFactory.java:93)
at org.springframework.context.annotation.ConfigurationClassParser.asSourceClass(ConfigurationClassParser.java:597)
at org.springframework.context.annotation.ConfigurationClassParser.asSourceClass(ConfigurationClassParser.java:555)
at org.springframework.context.annotation.ConfigurationClassParser.processConfigurationClass(ConfigurationClassParser.java:228)
at org.springframework.context.annotation.ConfigurationClassParser.parse(ConfigurationClassParser.java:197)
at org.springframework.context.annotation.ConfigurationClassParser.parse(ConfigurationClassParser.java:166)
at org.springframework.context.annotation.ConfigurationClassPostProcessor.processConfigBeanDefinitions(ConfigurationClassPostProcessor.java:306)
at org.springframework.context.annotation.ConfigurationClassPostProcessor.postProcessBeanDefinitionRegistry(ConfigurationClassPostProcessor.java:239)
at org.springframework.context.support.PostProcessorRegistrationDelegate.invokeBeanDefinitionRegistryPostProcessors(PostProcessorRegistrationDelegate.java:254)
at org.springframework.context.support.PostProcessorRegistrationDelegate.invokeBeanFactoryPostProcessors(PostProcessorRegistrationDelegate.java:94)
at org.springframework.context.support.AbstractApplicationContext.invokeBeanFactoryPostProcessors(AbstractApplicationContext.java:610)
at org.springframework.context.support.AbstractApplicationContext.refresh(AbstractApplicationContext.java:462)
-locked (a java.lang.Object)
at org.springframework.context.support.ClassPathXmlApplicationContext.(ClassPathXmlApplicationContext.java:139)
at org.springframework.context.support.ClassPathXmlApplicationContext.(ClassPathXmlApplicationContext.java:93)
at App2.main(App2.java:133) *// new ClassPathXmlApplicationContext() を実行している処理です。

Locked ownable synchronizers:
-None


ロックの可能性が高いと思うのですが、ロックがかかりっぱなしになる原因が思い当たりません。
ガベージコレクションが悪さをしているのでしょうか。

同様の事象発生や何か原因として考えられる情報がありましたら、ご教示下さい。

●補足事項
・実装したアプリケーションではスレッドは使用していません。
・アプリケーションは1分毎に起動しており、処理が完了するとアプリケーションは終了する作りのため、
メモリリークでは無いと考えています。
(但し、0.5秒ずつずらして、引数の異なる同じアプリケーションを最大14個動作させています)
・アプリケーションがフリーズした状態でもCPU使用率は高い状態でした。
(CPUの1スレッドを専有しており100%使用状態となっていた)
・発生頻度は、4台のサーバで1分ごとに動作して、1ヶ月に1回発生するかくらいです。

回答

CPU使用率が高いなら、ロックではなく無限ループの可能性の方が高いと思います。
デバッグログを出力できるようにして、どこでループしているのか観測してみてください。

編集 履歴 (0)
ウォッチ

この質問への回答やコメントをメールでお知らせします。