Details
-
Bug
-
Resolution: Unresolved
-
Major
-
None
-
1.2.3
-
None
-
None
-
jdk8
Description
Multithreaded java service in a docker container
Threadpool with each thread doing logging
high request rate
Logging policy is
<appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender"> <encoder> <pattern>%d\{HH:mm:ss.SSS} [%thread] %-5level %logger\{5} - %msg%n</pattern> </encoder> </appender> <appender name="FILE" class="ch.qos.logback.core.rolling.RollingFileAppender"> <file>logs/kafkaconsumer.log</file> <encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder"> <Pattern> %d\{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger\{5} - %msg%n </Pattern> </encoder> <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy"> <!-- rollover daily --> <fileNamePattern>logs/kafkaconsumer.%d\{yyyy-MM-dd}.%i.log </fileNamePattern> <timeBasedFileNamingAndTriggeringPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP"> <maxFileSize>10MB</maxFileSize> </timeBasedFileNamingAndTriggeringPolicy> </rollingPolicy> </appender> <logger name="com.k2io" level="INFO" additivity="false"> <appender-ref ref="STDOUT" /> <appender-ref ref="FILE" /> </logger>
Deadlock occurs after running for several hours
A number of threads like the one below waiting for 0x00000003c0658e90
"pool-6-thread-110" #155 prio=5 os_prio=0 tid=0x00007f90c80b1000 nid=0xd7 waiting on condition [0x00007f8fd59d8000] java.lang.Thread.State: WAITING (parking) at sun.misc.Unsafe.park(Native Method) - parking to wait for <0x00000003c0658e90> (a java.util.concurrent.locks.ReentrantLock$NonfairSync) at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175) at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:836) at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:870) at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1199) at java.util.concurrent.locks.ReentrantLock$NonfairSync.lock(ReentrantLock.java:209) at java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:285) at ch.qos.logback.core.OutputStreamAppender.writeBytes(OutputStreamAppender.java:197) at ch.qos.logback.core.OutputStreamAppender.subAppend(OutputStreamAppender.java:231) at ch.qos.logback.core.OutputStreamAppender.append(OutputStreamAppender.java:102) at ch.qos.logback.core.UnsynchronizedAppenderBase.doAppend(UnsynchronizedAppenderBase.java:84) at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:51) at ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:270) at ch.qos.logback.classic.Logger.callAppenders(Logger.java:257) at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:421) at ch.qos.logback.classic.Logger.filterAndLog_0_Or3Plus(Logger.java:383) at ch.qos.logback.classic.Logger.info(Logger.java:579) at com.k2io.validator.repository.ValidationRepository.constructPmapWithTrail(ValidationRepository.java:555) at com.k2io.validator.ValidationService$ValidationCallable.getAgrePmap(ValidationService.java:329) at com.k2io.validator.ValidationService$ValidationCallable.call(ValidationService.java:167) at com.k2io.validator.ValidationService$ValidationCallable.call(ValidationService.java:70) at java.util.concurrent.FutureTask.run(FutureTask.java:266) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) at java.lang.Thread.run(Thread.java:748)
And 0x00000003c0658e90 is held by the following thread
"pool-6-thread-87" #129 prio=5 os_prio=0 tid=0x00007f90d405d000 nid=0xb6 runnable [0x00007f8fd73f2000] java.lang.Thread.State: RUNNABLE at java.io.FileOutputStream.writeBytes(Native Method) at java.io.FileOutputStream.write(FileOutputStream.java:326) at java.io.BufferedOutputStream.write(BufferedOutputStream.java:122) - locked <0x00000003c06e8890> (a java.io.BufferedOutputStream) at java.io.PrintStream.write(PrintStream.java:480) - locked <0x00000003c06e8870> (a java.io.PrintStream) at java.io.FilterOutputStream.write(FilterOutputStream.java:97) at ch.qos.logback.core.joran.spi.ConsoleTarget$1.write(ConsoleTarget.java:37) at ch.qos.logback.core.OutputStreamAppender.writeBytes(OutputStreamAppender.java:199) at ch.qos.logback.core.OutputStreamAppender.subAppend(OutputStreamAppender.java:231) at ch.qos.logback.core.OutputStreamAppender.append(OutputStreamAppender.java:102) at ch.qos.logback.core.UnsynchronizedAppenderBase.doAppend(UnsynchronizedAppenderBase.java:84) at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:51) at ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:270) at ch.qos.logback.classic.Logger.callAppenders(Logger.java:257) at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:421) at ch.qos.logback.classic.Logger.filterAndLog_0_Or3Plus(Logger.java:383) at ch.qos.logback.classic.Logger.info(Logger.java:579) at com.k2io.validator.repository.ValidationRepository.constructPmapWithTrail(ValidationRepository.java:555) at com.k2io.validator.ValidationService$ValidationCallable.getAgrePmap(ValidationService.java:329) at com.k2io.validator.ValidationService$ValidationCallable.call(ValidationService.java:167) at com.k2io.validator.ValidationService$ValidationCallable.call(ValidationService.java:70) at java.util.concurrent.FutureTask.run(FutureTask.java:266) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) at java.lang.Thread.run(Thread.java:748) Locked ownable synchronizers: - <0x00000003c0658e90> (a java.util.concurrent.locks.ReentrantLock$NonfairSync) - <0x00000003c11c30e8> (a java.util.concurrent.ThreadPoolExecutor$Worker)