【已结算】Java logback大量线程 WAITING on java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject【赏金20元】
问题:
生产cat监控报警,某台机器上出现大量请求超时,从cat监控上看有请求返回时间高达40s以上。
环境:
linux、JDK1.7、CMS
slf4j-api 1.7.25以及1.7.21(1.7.21冲突了)
logback-core 1.2.3
JVM参数配置如下:
-server -Xms4g -Xmx4g -Xmn1536m -XX:SurvivorRatio=8 -XX:PermSize=256M -XX:+DisableExplicitGC -XX:ConcGCThreads=4 -XX:ParallelGCThreads=4 -XX:+UseConcMarkSweepGC -XX:+UseParNewGC -XX:+CMSParallelRemarkEnabled -XX:CMSInitiatingOccupancyFraction=70 -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintGCApplicationStoppedTime -Xloggc:/home/dx01/dump/gc.log -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/home/dx01/dump/cust_image_$filename
logback.xml配置如下:
<property name="logback.encoding" value="UTF-8" />
<!-- 统一日志格式输出用|分隔方便 elk日志工具收集处理 ,默认日志格式是 时间|级别|日志戳|代码路径|扩展json(收集图表数据,无则域留空)|脱敏后日志内容 -->
<property name="logback.pattern"
value="%date{yyyy-MM-dd HH:mm:ss.SSS}|%-5level|%logPreFix|%class.%method:%line|%extjson|%sensitiveMsg%n" />
<!-- 错误日志输出格式, 默认日志格式是 时间|级别|日志戳|代码路径|扩展json(收集图表数据,无则域留空)|脱敏后日志内容 -->
<property name="logback.pattern.error"
value="%date{yyyy-MM-dd HH:mm:ss.SSS}|%-5level|%logPreFix|%class.%method:%line|%extjson|%sensitiveMsg%n" />
<!-- 设置控制台日志 -->
<appender name="stdout" class="XXX.log.logback.appender.ExtConsoleAppender">
<encoder class="ch.qos.logback.core.encoder.LayoutWrappingEncoder">
<layout class="XXX.log.logback.layout.ExtLayout">
<pattern>${logback.pattern}</pattern>
<charset>${logback.encoding}</charset>
</layout>
</encoder>
</appender>
<appender name="DEBUG_FILE"
class="ch.qos.logback.core.rolling.RollingFileAppender">
<file>${logback.logpath}/debug.log</file>
<!-- see https://logback.qos.ch/manual/filters.html -->
<filter class="ch.qos.logback.classic.filter.LevelFilter">
<level>DEBUG</level>
<onMatch>ACCEPT</onMatch>
<onMi**atch>DENY</onMi**atch>
</filter>
<!-- see https://logback.qos.ch/manual/appenders.html#SizeAndTimeBasedFNATP -->
<rollingPolicy
class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
<fileNamePattern>${logback.logpath}/debug.%d{yyyyMMdd}.%i.log
</fileNamePattern>
<maxFileSize>${logback.maxFileSize}</maxFileSize>
</rollingPolicy>
<encoder class="ch.qos.logback.core.encoder.LayoutWrappingEncoder">
<!-- see https://logback.qos.ch/manual/layouts.html -->
<layout class="XXX.log.logback.layout.ExtLayout">
<pattern>${logback.pattern.error}</pattern>
<charset>${logback.encoding}</charset>
</layout>
</encoder>
</appender>
<appender name="INFO_FILE"
class="ch.qos.logback.core.rolling.RollingFileAppender">
<file>${logback.logpath}/info.log</file>
<!-- see https://logback.qos.ch/manual/filters.html -->
<filter class="ch.qos.logback.classic.filter.LevelFilter">
<level>INFO</level>
<onMatch>ACCEPT</onMatch>
<onMi**atch>DENY</onMi**atch>
</filter>
<!-- see https://logback.qos.ch/manual/appenders.html#SizeAndTimeBasedFNATP -->
<rollingPolicy
class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
<fileNamePattern>${logback.logpath}/info.%d{yyyyMMdd}.%i.log
</fileNamePattern>
<maxFileSize>${logback.maxFileSize}</maxFileSize>
</rollingPolicy>
<encoder class="ch.qos.logback.core.encoder.LayoutWrappingEncoder">
<!-- see https://logback.qos.ch/manual/layouts.html -->
<layout class="XXX.log.logback.layout.ExtLayout">
<pattern>${logback.pattern}</pattern>
<charset>${logback.encoding}</charset>
</layout>
</encoder>
</appender>
<appender name="ERROR_FILE"
class="ch.qos.logback.core.rolling.RollingFileAppender">
<file>${logback.logpath}/error.log</file>
<filter class="ch.qos.logback.classic.filter.ThresholdFilter">
<level>WARN</level>
</filter>
<rollingPolicy
class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
<fileNamePattern>${logback.logpath}/error.%d{yyyyMMdd}.%i.log
</fileNamePattern>
<maxFileSize>${logback.maxFileSize}</maxFileSize>
</rollingPolicy>
<encoder class="ch.qos.logback.core.encoder.LayoutWrappingEncoder">
<layout class="XXX.log.logback.layout.ExtLayout">
<pattern>${logback.pattern.error}</pattern>
<charset>${logback.encoding}</charset>
</layout>
</encoder>
</appender>
<appender name="file.cat.monitor" class="ch.qos.logback.core.rolling.RollingFileAppender">
<File>${logback.logpath}/monitor/cat.log</File>
<rollingPolicy class="ch.qos.logback.core.rolling.FixedWindowRollingPolicy">
<fileNamePattern>${logback.logpath}/monitor/cat.%i.log</fileNamePattern>
<minIndex>1</minIndex>
<maxIndex>3</maxIndex>
</rollingPolicy>
<triggeringPolicy class="ch.qos.logback.core.rolling.SizeBasedTriggeringPolicy">
<maxFileSize>15MB</maxFileSize>
</triggeringPolicy>
<encoder>
<pattern>%msg%n</pattern>
</encoder>
<filter class="ch.qos.logback.classic.filter.LevelFilter">
<level>INFO</level>
<onMatch>ACCEPT</onMatch>
<onMi**atch>DENY</onMi**atch>
</filter>
</appender>
<logger name="XXXX.MyMessageSender" additivity="false">
<level value="info"/>
<appender-ref ref="file.cat.monitor"/>
</logger>
<!-- 用来设置某一个包或者某一个类的日志打印级别 -->
<logger name="org.springframework" level="warn" />
<logger name="org.apache" level="info" />
<logger name="org.aspectj.weaver" level="warn" />
<logger name="org.hibernate" level="OFF" />
<logger name="com.mchange" level="OFF" />
<logger name="java.sql.Connection" level="debug" />
<logger name="java.sql.Statement" level="debug" />
<logger name="java.sql.ResultSet" level="debug" />
<logger name="java.sql.PreparedStatement" level="debug" />
<logger name="org.apache.commons.httpclient" level="OFF" />
<logger name="org.apache.commons.httpclient.Wire" level="OFF" />
<logger name="httpclient" level="error" />
<logger name="httpclient.wire.content" level="error" />
<logger name="httpclient.wire.header" level="error" />
<logger name="com.alibaba.dubbo" additivity="true" level="ERROR" />
<root level="${logback.rootLoggerLevel}">
<appender-ref ref="DEBUG_FILE" />
<appender-ref ref="INFO_FILE" />
<appender-ref ref="ERROR_FILE" />
<!-- 控制台日志放在最后解析 -->
<appender-ref ref="stdout" />
</root>
</configuration>
已有资料:
1、有当时的GC日志,从GC来看,存在大量 (concurrent mode failure) 错误,并导致应用长时间停顿12s以上。
而且,随着时间的推移,FGC回收的内存越来越少,可以看到回收前后的堆内存大小几乎没有变化,由于及时关闭了流量入口,因此应用并没有发生OOM,没有生成dump文件。
有JStack保存的线程信息,可以发现1772(3544/2)个线程都在等待logback日志打印的一个锁。服务高峰期启动了1000个dubbo线程(rpc),800个catalina线程(http)。
但是这个锁对象看不出来被哪个线程持有了,处于什么状态。
WAITING on java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@11c0ebf3
3、没有当时故障的内存dump,但是5月份时有一次OOM,生成了dump文件,错误原因和本次事故非常相似(也是logback日志输出等待锁)。
4、后面从运维那边得知此次事故发生前两三分钟,又一波流量高峰。(但排除流量达到logback上限导致,因为其他机器在负载均衡的情况下并无问题)
尝试过的方法:
1、由于GC现象+线程现象来看,在首次发生 (concurrent mode failure) 错误时,转为Serial Old单线程进行FGC,可以看到堆内存并没有得到有效的回收(回收后还有2567148K)。
(concurrent mode failure): 2435075K->2567148K(2621440K), 18.5602110 secs] 3837609K->2567148K(4037056K), [CMS Perm : 134518K->122230K(262144K)], 18.5610610 secs] [Times: user=10.64 sys=0.04, real=18.57 secs]
2022-07-04T09:19:55.925+0800: 2106543.896: Total time for which application threads were stopped: 18.5650080 seconds
说明在触发Serial Old GC时,已经存在大量对象存活的问题了,因此,应该可以排除GC停顿导致的请求积压问题,进而导致故障的发生。
2、因此,极有可能是大量线程处于WAITING状态,没有释放对象等资源,导致GC无法有效回收堆内存。进而导致新对象无法分配内存时,JVM频繁地触发CMS回收并失败,然后触发(concurrent mode failure) 。
3、有找到一篇文章,现象和这次故障非常相似,但是在引发这个问题的原因不太一致:
网友案例分析(需要科学上网)
从网友分析的情况来看,是因为配置了压缩日志文件(.gz)、并且单个日志文件特别大(4G)、而且配置的是FixedWindowRollingPolicy。从而导致在压缩复制日志文件时出现较长耗时,进而阻塞了日志写入队列。
但我们的应用单个日志文件只有500M,而且日志文件并没有压缩,理论上不会出现卡顿(或者说卡顿只会导致一瞬间的请求耗时增加)。
4、在logback官网中查看了一些bug提交记录,但大多数类似的问题都处于没有结论,也未解决的状态:
https://jira.qos.ch/browse/LOGBACK-1406
如果是控制台日志死循环,那么CPU load应该升高,但实际上没有,因此可以排除。(后续这边也会考虑去掉控制台日志append输出)
提问:
请问下各位大佬,排查这个问题还有其他思路吗?或者有无遇到过这个问题,能否复现并最终解决呢?
麻烦大家关注【Heapdump性能社区】公众号,及时接收信息!