使用布谷鸟过滤器对 logback 日志一定周期内重复异常堆栈打印进行压缩过滤

866 阅读3分钟

前因

前阵子日子线上有个bug,但是由于触发过于频繁导致日志打印全是这个bug的堆栈,全是重复堆栈内容日志一下变得不友好起来,搜索有没有什么优化办法。

偶然看到近期业务大量突增微服务性能优化总结-2.开发日志输出异常堆栈的过滤插件这篇文章,试图将同样的日志堆栈过滤插件复刻到logback中

后来发现堆栈打印还是至少同样的堆栈一天内至少打印一次(日志文件按照天进行拆分)才方便排查,于是就需要判断一个异常的堆栈是否打印过,自然就想到了大名鼎鼎的布隆过滤器和布谷鸟过滤器,遂进行改造

思路

思路是改造ch.qos.logback.classic.pattern.ThrowableProxyConverter ,通过在logback配置中设置日志输出的PATTERNconverterClass 来取代默认的org.springframework.boot.logging.logback.ExtendedWhitespaceThrowableProxyConverter

然后在isIgnoredStackTraceLine方法中加入自定义的过滤逻辑

判断是否重复使用布隆和布谷鸟过滤器

代码及演示Demo

全部代码 👉 GitHub:LogNoiseLess

因为有对logback类的copy改造,还涉及到spring环境变量加载和日志系统加载打印的先后关系、日志异常插件自己报异常怎么debug等一堆小坑,代码比较多,建议用的时候可以直接fork改改

这里只看核心的两个方法: 一个是判断该行是否应该被过滤

@Override
protected boolean isIgnoredStackTraceLine(String line) {
    //...
    try {
        // 具体判断逻辑委托给接口的实现类
        return predicate.isShouldSkipLine(line);
    } catch (Exception e) {
        //...
    }
    return super.isIgnoredStackTraceLine(line);
}

一个判断该异常堆栈是否第一次打印,这里使用弱引用key Cache是因为logback对于同一个异常会多次调用这个方法

//...
@Override
public boolean isShouldEnableSkip(IThrowableProxy throwableProxy) {
    //如果 mightContain false 则直接判断为打印完整堆栈(return false)
    return Boolean.TRUE.equals(RESULT_CACHE.get().get(throwableProxy, k -> autoRebuildCuckooFilter.isFull(k.getStackTraceElementProxyArray())));
}
//...
public boolean isFull(T item) {
    //判断是否是新的周期新建过滤器
    CuckooFilter<T> cuckooFilter = rebuildIfNecessary();
    //...
    //交给布谷鸟过滤器或者布隆过滤器来判断是否打印过
    if (cuckooFilter.approximateCount(item) >= times) {
        return true;
    }
    return !cuckooFilter.put(item);
}
//...

使用及效果

如下示例logback配置

<?xml version="1.0" encoding="UTF-8"?>
<configuration>
    <!--  导入spring基础配置  -->
    <include resource="org/springframework/boot/logging/logback/defaults.xml"/>
    <!-- 因为覆盖了属性,所以这里不能直接借用  -->
<!--    <include resource="org/springframework/boot/logging/logback/console-appender.xml"/>-->

    <!--  替换defaults.xml中定义的属性, 使用自己的噪音抑制异常转换器 -->
    <conversionRule conversionWord="wEx"
                    converterClass="com.muyuanjin.lognoiseless.NoiseLessThrowableProxyConverter"/>

    <!-- 控制台日志,因为覆盖了属性,所以这里不能直接借用 console-appender.xml ,copy一遍-->
    <appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <pattern>${CONSOLE_LOG_PATTERN}</pattern>
            <charset>${CONSOLE_LOG_CHARSET}</charset>
        </encoder>
    </appender>
    <root level="INFO">
        <appender-ref ref="CONSOLE"/>
    </root>
</configuration>

然后在spring yaml配置文件配置: 白名单模式

logback:
  stackTrace:
    skipLine: com.example,java,org # 多个包名以逗号分隔
    skipLineMode: whitelist #白名单模式
    maxNumPerCycle: 1 # 每个周期内最大打印全栈的次数,=0时每次均跳过, =1时使用 布隆过滤器
    cycleDuration: 2h #计数周期

或者黑名单模式

logback:
  stackTrace:
    skipLine: com.example,java,org # 多个包名以逗号分隔
    skipLineMode: blacklist #黑名单模式
    maxNumPerCycle: 1 # 每个周期内最大打印全栈的次数,=0时每次均跳过, =1时使用 布隆过滤器
    cycleDuration: 2h #计数周期

或者 class 或 spring bean (需实现StackLineSkipPredicate)

logback:
  stackTrace:
    skipLine: com.example.TestStackLineSkipPredicate
    skipLineMode: predicate_class #谓词类
    maxNumPerCycle: 1 # 每个周期内最大打印全栈的次数,=0时每次均跳过, =1时使用 布隆过滤器
    cycleDuration: 2h #计数周期

或者 janino表达式,使用 line 表示该行的字符串参数, 返回true时表示不打印改行

logback:
  stackTrace:
    skipLine: "!line.contains(\"com.example\")" #必须以com.example开头才打印
    skipLineMode: janino_expression #janino表达式
    maxNumPerCycle: 1 # 每个周期内最大打印全栈的次数,=0时每次均跳过, =1时使用 布隆过滤器
    cycleDuration: 2h #计数周期

运行 demo 里的 Test 查看效果:

@Slf4j
@SpringBootTest
class LogNoiseLessDemoApplicationTests {

    @Test
    void contextLoads() {
        for (int i = 0; i < 5; i++) {
            log.warn("test", new RuntimeException("test"));
        }
    }
}

image.png

OK,搞定