Logback日志滚动陷阱

spilledyear
2,357 阅读7分钟

背景介绍

有个业务方从虚拟机切到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. 虚心好学：哪里有那么多天才，就算有和你也没关系，既然你不是，就勤奋一点呗。一个人的能力总是有限的，特别是普通人，多个人多个想法，讨论讨论，说不定有其他收获
avatar
文章
阅读
粉丝