QA@IT
«質問へ戻る

質問を投稿

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

●環境

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回発生するかくらいです。

## ●環境
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 <0x00000000f05a74e0> (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 <0x00000000f03b8020> (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 <0x00000000f04f9270> (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 <0x00000000f04980b0> (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 <0x00000000f0498740> (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 <0x00000000fffbf778> (a java.lang.ref.ReferenceQueue$Lock)
>   at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:143)
>   -locked <0x00000000fffbf778> (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 <0x00000000ffe71a10> (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 <0x00000000ffe71a10> (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.<init>(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 <0x00000000fecc8bb8> (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 <0x00000000fffc9290> (a java.lang.Object)
>   at org.springframework.context.support.ClassPathXmlApplicationContext.<init>(ClassPathXmlApplicationContext.java:139)
>   at org.springframework.context.support.ClassPathXmlApplicationContext.<init>(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回発生するかくらいです。