Logback日志滚动陷阱

·  阅读 778

背景介绍

有个业务方从虚拟机切到k8s之后,每到整点,都会收到Dubbo线程池溢出告警,观察监控发现CPU、内存使用率都不高整点过后Dubbo线程池又很平稳。还有一个需要注意的地方是:在整点前后Dubbo线程数为10-20,但整点的时候线程数却来到了400-500,这就有点夸张了

可能有人会说是不是因为整点业务量比较大?没错,整点业务量是要大一点,但也远不到这种程度,看监控调用量也就多了5% -10%,并且这时候通过监控发现CPU、内存使用率都不高。

问题定位

以上是背景,我们的目标就是找出问题原因。以下是问题定位过程:

1、 查看线程堆栈信息。好在该问题复现比较容易,Dubbo在线程池溢出的时候,默认会将当时的线程Dump信息保存到用户目录。通过对线程堆栈的查看,发现大部分线程都BLOCK在loback写日志上了:如下

"DubboServerHandler-172.21.41.166:20833-thread-111" Id=253 BLOCKED on ch.qos.logback.core.rolling.TimeBasedRollingPolicy@288c40d owned by "DubboServerHandler-172.21.41.166:20833-thread-75" Id=200
	at ch.qos.logback.core.rolling.RollingFileAppender.subAppend(RollingFileAppender.java:229)
	-  blocked on ch.qos.logback.core.rolling.TimeBasedRollingPolicy@288c40d
	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.warn(Logger.java:688)
        ......
	at org.apache.dubbo.common.bytecode.Wrapper36.invokeMethod(Wrapper36.java)
	at org.apache.dubbo.rpc.proxy.javassist.JavassistProxyFactory$1.doInvoke(JavassistProxyFactory.java:47)
	at org.apache.dubbo.rpc.proxy.AbstractProxyInvoker.invoke(AbstractProxyInvoker.java:84)
	at org.apache.dubbo.config.invoker.DelegateProviderMetaDataInvoker.invoke(DelegateProviderMetaDataInvoker.java:56)
	at org.apache.dubbo.rpc.protocol.InvokerWrapper.invoke(InvokerWrapper.java:56)
	at com.alibaba.csp.sentinel.adapter.dubbo.SentinelDubboProviderFilter.invoke(SentinelDubboProviderFilter.java:65)
	at org.apache.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:83)
	...

	Number of locked synchronizers = 1
	- java.util.concurrent.ThreadPoolExecutor$Worker@1a579e21



// 看看 DubboServerHandler-172.21.41.166:20833-thread-75 线程干了啥

"DubboServerHandler-172.21.41.166:20833-thread-75" Id=200 RUNNABLE
	at ch.qos.logback.core.rolling.RollingFileAppender.subAppend(RollingFileAppender.java:229)
	-  locked ch.qos.logback.core.rolling.TimeBasedRollingPolicy@288c40d
	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.tuya.aries.biz.service.category.impl.CategoryBizService$afterPropertiesSet$1.onRemoval(CategoryBizService.kt:65)
	at com.google.common.cache.LocalCache.processPendingNotifications(LocalCache.java:1963)
	at com.google.common.cache.LocalCache$Segment.runUnlockedCleanup(LocalCache.java:3562)
	at com.google.common.cache.LocalCache$Segment.postWriteCleanup(LocalCache.java:3538)
	at com.google.common.cache.LocalCache$Segment.storeLoadedValue(LocalCache.java:3226)
	at com.google.common.cache.LocalCache$Segment.getAndRecordStats(LocalCache.java:2378)
	at com.google.common.cache.LocalCache$Segment.loadSync(LocalCache.java:2337)
	at com.google.common.cache.LocalCache$Segment.lockedGetOrLoad(LocalCache.java:2295)
	-  locked com.google.common.cache.LocalCache$StrongAccessWriteEntry@52efd51e
	at com.google.common.cache.LocalCache$Segment.get(LocalCache.java:2208)
	at com.google.common.cache.LocalCache.get(LocalCache.java:4053)
	at com.google.common.cache.LocalCache.getOrLoad(LocalCache.java:4057)
	at com.google.common.cache.LocalCache$LocalLoadingCache.get(LocalCache.java:4986)
	at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:204)
	at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:736)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:157)
	at org.springframework.aop.framework.adapter.MethodBeforeAdviceInterceptor.invoke(MethodBeforeAdviceInterceptor.java:56)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:168)
	at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:92)
	...

	Number of locked synchronizers = 1
	- java.util.concurrent.ThreadPoolExecutor$Worker@146c6130
复制代码

大部分线程在写日志的时候要获取锁,该锁被线程DubboServerHandler-172.21.41.166:20833-thread-75持有,通查看logback源码的,发现此时在做日志滚动操作,这是一个同步操作

表面上原因就是这样了,logback日志滚动是同步操作,导致大部分业务线程都阻塞在日志滚动上。为了验证自己的猜想,我查看了业务方配置的logback.xml,该配置确实是整点滚动,如下:

<appender name="InfoFile" class="ch.qos.logback.core.rolling.RollingFileAppender">
    <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
        <level>INFO</level>
    </filter>
    <file>${loggingRoot}/info.log</file>
    <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
        <FileNamePattern>${loggingRoot}/info_%d{yyyy-MM-dd.HH}.log</FileNamePattern>
        <MaxHistory>7</MaxHistory>
    </rollingPolicy>
    <encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
        <pattern>%d{yyyy-MM-dd HH:mm:ss.SSS}, %p, %c, %F, %L, %M %m%n</pattern>
    </encoder>
</appender>
复制代码

到这里,我在心里想当然的有了第一个结论:业务整点调用量较大,恰巧logback此时又发生了日志滚动,所以导致了这个问题。其实后面想想就不太对,为啥在虚拟机上没问题上k8s就有问题了?不过这个后面再说。为了验证这个猜想,我通过以下方法进行验证:

  1. 将日志滚动方式改成了按大小滚动:结果啪啪打脸
  2. 还是不甘心,将日志改成异步: 结果啪啪打脸
  3. 检查了业务方logback.xnl配置文件,并没有什么特别的地方

到这里大概可以想到,这个问题应该和logback本身没有什么关系,但肯定和日志输出有点关系,线程堆栈上明写着啊,要不然怎么解释。继续在这里纠结估计也不会有什么收获,这时候我们将关注点放到了k8s上。

2、运维提示到,业务方切到的那台k8s机器上没有上SSD。马上对这个猜想进行验证,结果啪啪打脸

到这里大家都有点疲惫了,到底是什么鬼原因导致的这个问题?一下子没什么想法,于是提供了一个临时解决办法:

  1. 调大Dubbo线程数:看监控此时得CPU、内存使用率都比较低,把Dubbo线程数调大一点,至少不会线程池溢出,最多就是整点得时候响应时间变长一些
  2. 加副本:每个节点的流量变小了,线程池溢出的概率肯定更低。知道加机器不太合理,但如果直接下k8s,这个问题就真不好排查了

就这样子下来,线程池确实不溢出了,但是通过监控观察,一到整点Dubbo线程数占用还是比平高了好几个等级,业务方不放心,还是要切回去。也能理解,看着这监控就难受,问题不解决,谁敢用?

这时候我刚好在测试公司日志组件的日志滚动策略。本地测试没啥问题,打算将程序部署到k8s先跑几天看看。我配置的日志滚动策略是按大小滚动,大小限制为800MB,但无意间在k8s上发现一个现象:日志文件每到500MB的时候,文件就会被清0。突然就有了什么想法,赶快找运维确认:k8s机器上有个后台任务会去清理日志文件,如果日志文件大于500MB,直接将其内容清除,通过和运维确认,在其执行清除动作的时候,文件句柄占用好几秒

到这里,问题原因基本确定了,运维将该任务关掉之后,所有业务方都正常了。

问题总结

k8s机器上有定时任务清除那些大于500MB的日志文件,业务方的日志也真是巧了,基本一个小时的日志大小就是500MB左右。在整点的时候,定时任务清理日志文件,占有文件句柄数秒,logback整点要执行日志滚动,也就是要对日志文件重命名,这时候该线程占用了loback中的一把锁,其他业务线程在输出日志时需要先获取那把锁,最终导致阻塞的线程数越来越多,最终Dubbo线程池溢出

那么通过这次问题排查,有什么收获?怎么说,虽然回过头来看问题很简单,但毕竟也是全程参与,其实有很多看似很棘手的问题可能本身确实不复杂,查出来了就简单,没查出来就背锅。关键还是要从中学到什么吧,问题本身可能并不是很有价值,不见得以后还会遇到这种问题,但问题排查过程却是很有价值得,说到底就是经验:

  1. 开阔的思维:一个问题,从表面来看可能是A的问题,实际上有可能是B+C+D+E+F+G造成的。就像上面那个问题,表面看是logback的原因,实际上却是种种原因的组合 + 巧合。那该如何开阔思维?说到底就是让自己的知识面更广一些,一方面是对工作中常用框架的掌握,这一方面只能说是多多益善吧,高效、持续学习;另一方面是一些工作时表面用不到,实际却很有用的知识掌握,比如说操作系统等基础知识,用到的时候会很有帮助。自己懂得越多,面对问题时能考虑到的点就越多,也算是经验吧。
  2. 严谨的态度:光思维开阔还不行,还要有严谨的态度。开阔的思维会让你有更多的思路,但如果态度不严谨,很可能在正确的方向上半途而废,然后陷入其他错误的方向中。还是以上面的问题为例:为什么我在测试日志滚动策略的时候不去看看文件的大小呢?为什么不看看整点时日志文件的变化呢?有了一个想法就想当然的以为是这样,验证失败之后就把这个方向堵死,如此以往,白白浪费时间
  3. 梳理总结:在没有思路的时候,不妨在白纸上把想到的点都写下来,然后进行梳理,这样更不容易错过细节。就像警察破案一样,他们在找凶手,你在找Bug
  4. 虚心好学:哪里有那么多天才,就算有和你也没关系,既然你不是,就勤奋一点呗。一个人的能力总是有限的,特别是普通人,多个人多个想法,讨论讨论,说不定有其他收获
分类:
后端
标签: