性能问答>【已结算】Java logback大量线程 WAITING on java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject【赏金20元】>
13回复
2年前

【已结算】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以上。
5C372B44478A4ECDB0D52A9B5B700701.png

而且,随着时间的推移,FGC回收的内存越来越少,可以看到回收前后的堆内存大小几乎没有变化,由于及时关闭了流量入口,因此应用并没有发生OOM,没有生成dump文件。
BCD4F720BB0C4950ACFEDAA24D8B1985.png

有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性能社区】公众号,及时接收信息!

2557 阅读
请先登录,查看13条精彩评论吧
快去登录吧,你将获得
  • 浏览更多精彩评论
  • 和开发者讨论交流,共同进步