레벨 필터를 잘못 구성하면 로그가 중복됩니다

• 콘솔에 로그를 기록하는 동안 로그 기록은 서로 다른 레벨에 따라 두 개의 파일에 기록됩니다.
  

• 실행 결과

• info.log 파일에는 INFO, WARN이 포함됩니다. 예상과 다른 ERROR 3레벨 로그
  

• error.log에는 WARN 및 ERROR 레벨 로그가 포함되어 반복적으로 로그가 수집됩니다

• Accident Accountability
  일부 회사에서는 자동화된 ELK 솔루션을 사용하여 로그를 수집합니다. 그리고 로그는 동시에 수집되어 콘솔과 파일로 출력됩니다. 개발자는 로컬에서 테스트할 때 파일에 기록된 로그에 신경 쓰지 않습니다. 테스트 및 프로덕션 환경에서는 개발자에게 서버 액세스 권한이 없기 때문에 문제가 반복됩니다. 원본 로그 파일에서는 찾기가 어렵습니다.

로그가 반복되는 이유는 무엇인가요?

ThresholdFilter 소스 코드 분석

• 로그 수준 ≥ 구성 수준이 日志级别 ≥ 配置级别 返回NEUTRAL，继续调用过滤器链上的下个过滤器
• 否则返回DENY，直接拒绝记录日志
  

该案例我们将 ThresholdFilter 置 WARN，因此可记录WARN和ERROR级日志。

LevelFilter

用于比较日志级别，然后进行相应处理。

• 若匹配就调用onMatch定义的处理方式：默认交给下一个过滤器处理（AbstractMatcherFilter基类中定义的默认值）
• 否则调用onMismatch定义的处理方式：默认也是交给下一个过滤器

和ThresholdFilter不同，LevelFilter仅配置level无法真正起作用。

由于未配置onMatch和onMismatch属性，所以该过滤器失效，导致INFO以上级别日志都记录了。

修正

配置LevelFilter的onMatch属性为ACCEPT，表示接收INFO级别的日志；配置onMismatch属性为DENY，表示除了INFO级别都不记录：

如此，_info.logNEUTRAL

DENY

이 경우에는
ThresholdFilter를 설정합니다. ~
WARN

WARN

및 ERROR 레벨 로그가 기록될 수 있습니다.

• 는 로그 수준을 비교한 다음 그에 따라 처리하는 데 사용됩니다.

onMatch를 호출합니다.
정의된 처리 방법: 기본적으로 다음 필터(AbstractMatcherFilter 기본 클래스에 정의된 기본값)로 넘겨집니다. 그렇지 않으면

가 호출됩니다. 정의된 처리 방법: 기본적으로 다음 필터에도 넘겨집니다. 필터

는
ThresholdFilter
, LevelFilter

所以日志大量写入才会旷日持久。如何才能实现大量日志写入时，不会过多影响业务逻辑执行耗时而影响吞吐量呢？

AsyncAppender

使用Logback的AsyncAppender

即可实现异步日志记录。AsyncAppender类似装饰模式，在不改变类原有基本功能情况下为其增添新功能。这便可把AsyncAppender附加在其他Appender，将其变为异步。

定义一个异步Appender ASYNCFILE，包装之前的同步文件日志记录的FileAppender， 即可实现异步记录日志到文件

• 记录1000次日志和10000次日志的调用耗时，分别是537毫秒和1019毫秒
  

异步日志真的如此高性能？并不，因为这并没有记录下所有日志。

AsyncAppender异步日志坑

• 记录异步日志撑爆内存
• 记录异步日志出现日志丢失
• 记录异步日志出现阻塞。

案例

模拟慢日志记录场景：
首先，自定义一个继承自ConsoleAppender的MySlowAppender，作为记录到控制台的输出器，写入日志时休眠1秒。

• 配置文件中使用AsyncAppender，将MySlowAppender包装为异步日志记录
  

• 测试代码
  

• 耗时很短但出现日志丢失：要记录1000条日志，最终控制台只能搜索到215条日志，而且日志行号变问号。
  

• 原因分析
  AsyncAppender提供了一些配置参数，而当前没用对。

源码解析

• includeCallerData
  默认false：方法行号、方法名等信息不显示
• queueSize
  控制阻塞队列大小，使用的ArrayBlockingQueue阻塞队列，默认容量256：内存中最多保存256条日志
• discardingThreshold
  丢弃日志的阈值，为防止队列满后发生阻塞。默认队列剩余容量 ＜ 队列长度的20%，就会丢弃TRACE、DEBUG和INFO级日志
• neverBlock
  控制队列满时，加入的数据是否直接丢弃，不会阻塞等待，默认是false
  • 队列满时：offer不阻塞，而put会阻塞
  • neverBlock为true时，使用offer

public class AsyncAppender extends AsyncAppenderBase<ILoggingEvent> {
	// 是否收集调用方数据
    boolean includeCallerData = false;
    protected boolean isDiscardable(ILoggingEvent event) {
        Level level = event.getLevel();
        // 丢弃 ≤ INFO级日志
        return level.toInt() <= Level.INFO_INT;
    }
    protected void preprocess(ILoggingEvent eventObject) {
        eventObject.prepareForDeferredProcessing();
        if (includeCallerData)
            eventObject.getCallerData();
    }}public class AsyncAppenderBase<E> extends UnsynchronizedAppenderBase<E> implements AppenderAttachable<E> {

	// 阻塞队列：实现异步日志的核心
    BlockingQueue<E> blockingQueue;
    // 默认队列大小
    public static final int DEFAULT_QUEUE_SIZE = 256;
    int queueSize = DEFAULT_QUEUE_SIZE;
    static final int UNDEFINED = -1;
    int discardingThreshold = UNDEFINED;
    // 当队列满时：加入数据时是否直接丢弃，不会阻塞等待
    boolean neverBlock = false;

    @Override
    public void start() {
       	...
        blockingQueue = new ArrayBlockingQueue<E>(queueSize);
        if (discardingThreshold == UNDEFINED)
        //默认丢弃阈值是队列剩余量低于队列长度的20%，参见isQueueBelowDiscardingThreshold方法
            discardingThreshold = queueSize / 5;
        ...
    }

    @Override
    protected void append(E eventObject) {
        if (isQueueBelowDiscardingThreshold() && isDiscardable(eventObject)) { //判断是否可以丢数据
            return;
        }
        preprocess(eventObject);
        put(eventObject);
    }

    private boolean isQueueBelowDiscardingThreshold() {
        return (blockingQueue.remainingCapacity() < discardingThreshold);
    }

    private void put(E eventObject) {
        if (neverBlock) { //根据neverBlock决定使用不阻塞的offer还是阻塞的put方法
            blockingQueue.offer(eventObject);
        } else {
            putUninterruptibly(eventObject);
        }
    }
    //以阻塞方式添加数据到队列
    private void putUninterruptibly(E eventObject) {
        boolean interrupted = false;
        try {
            while (true) {
                try {
                    blockingQueue.put(eventObject);
                    break;
                } catch (InterruptedException e) {
                    interrupted = true;
                }
            }
        } finally {
            if (interrupted) {
                Thread.currentThread().interrupt();
            }
        }
    }}

默认队列大小256，达到80%后开始丢弃<=INFO级日志后，即可理解日志中为什么只有两百多条INFO日志了。

queueSize 过大

可能导致OOM

queueSize 较小

默认值256就已经算很小了，且discardingThreshold设置为大于0（或为默认值），队列剩余容量少于discardingThreshold的配置就会丢弃<=INFO日志。这里的坑点有两个：

1. 因为discardingThreshold，所以设置queueSize时容易踩坑。
   比如本案例最大日志并发1000，即便置queueSize为1000，同样会导致日志丢失
2. discardingThreshold参数容易有歧义，它不是百分比，而是日志条数。对于总容量10000队列，若希望队列剩余容量少于1000时丢弃，需配置为1000

neverBlock 默认false

意味总可能会出现阻塞。

• 若discardingThreshold = 0，那么队列满时再有日志写入就会阻塞
• 若discardingThreshold != 0，也只丢弃≤INFO级日志，出现大量错误日志时，还是会阻塞

queueSize、discardingThreshold和neverBlock三参密不可分，务必按业务需求设置：

• 若优先绝对性能，设置neverBlock = true，永不阻塞
• 若优先绝不丢数据，设置discardingThreshold = 0，即使≤INFO级日志也不会丢。但最好把queueSize设置大一点，毕竟默认的queueSize显然太小，太容易阻塞。
• 若兼顾，可丢弃不重要日志，把queueSize设置大点，再设置合理的discardingThreshold

以上日志配置最常见两个误区

로그인 자체에 대한 오해를 살펴보겠습니다.

로그 자리 표시자를 사용하면 로그 수준을 판단할 필요가 없어지나요?

SLF4J의 {} 자리 표시자 구문은 로그가 실제로 기록될 때만 실제 매개변수를 가져오므로 로그 데이터 획득의 성능 문제를 해결합니다.
이게 맞나요?

• 인증코드: 결과를 반환하는데 1초가 걸립니다
  

DEBUG 로그를 기록하고 >=INFO 수준의 로그만 기록하도록 설정하면 프로그램도 1초가 걸리나요?
세 가지 테스트 방법:

• 문자열을 연결하여 SlowString을 기록합니다.
• 자리 표시자 방법을 사용하여 SlowString을 기록합니다.
• 먼저 로그 수준이 DEBUG를 활성화했는지 확인합니다.

처음 두 메서드는 모두 SlowString을 호출하므로 둘 다 1을 사용합니다. 두 번째 방법은 자리 표시자를 사용하여 SlowString을 기록하는 것입니다. 이 방법을 사용하면 String을 명시적으로 연결하지 않고도 Object를 전달할 수 있지만 이는 지연일 뿐입니다(로그가 기록되지 않으면 생략됩니다) Log 매개 변수 object.toString() 문자열 연결에 시간이 많이 걸립니다.

이 경우 로그 수준이 미리 결정되지 않은 이상 SlowString을 호출해야 합니다.
따라서 {}占位符을 사용하면 매개변수 값 획득이 지연되어 로그 데이터 획득의 성능 문제를 해결할 수 없습니다.

로그 수준을 미리 판단하는 것 외에도 람다 표현식을 통해 지연된 매개변수 내용을 얻을 수도 있습니다. 그러나 SLF4J의 API는 아직 람다를 지원하지 않으므로 Log4j2 로그 API를 사용하고 Lombok의 @Slf4j 주석을 **@Log4j2** 주석으로 바꿔서 람다 표현식 매개변수에 대한 메소드를 제공해야 합니다.

Call 이 디버그, 서명 Supplier와 같이 매개변수는 로그가 실제로 필요할 때까지 지연됩니다.

그래서 debug4는 SlowString 메소드를 호출하지 않습니다.

그냥 교체하세요. Log4j2 API를 사용하면 실제 로깅은 여전히 ​​Logback을 통해 이루어집니다. 이것이 SLF4J 적응의 이점입니다.

Summary