log4j2是apache提供的日志框架，其具有高性能，可扩展性强的特点。log4j2提供了一些默认的日志级别，
trace, debug, info, warn, error
在线上通常会打印info及info级别以上的日志，而debug日志通常用于在测试的时候开启, 所以我们需要在log4j2的配置文件中屏蔽debug日志的打印。通常为了实现上面的目标我们会这样做，
<loggers>
<Logger name="xxxx" level="info">
<AppenderRef ref="info-log" level="info"/>
<AppenderRef ref="warn-log" level="warn"/>
<AppenderRef ref="error-log" level="error"/>
</Logger>
</loggers>
上面的配置表示，当使用的Logger名字为xxxx的时候，默认的级别是info，也就是低于info级别的日志是不能打印的。而高于info级别的日志会根据配置的appender不同，打印到不同的文件中去。
但是最近看到一些工程为了不打印debug日志，进行了如下的配置，
<loggers>
<Logger name="xxxx" level="debug">
<AppenderRef ref="info-log" level="info"/>
<AppenderRef ref="warn-log" level="warn"/>
<AppenderRef ref="error-log" level="error"/>
</Logger>
</loggers>
上面的配置虽然也可以起到相同的效果，但是理论上性能是比第一种配置要差一些的。至于为什么我们需要从源码的角度分析下，我们进入到slf4j的Log4jLogger中，
@Override
public void debug(final String format) {
logger.logIfEnabled(FQCN, Level.DEBUG, null, format);
}
继续进入到logIfEnabled中，
@Override
public void logIfEnabled(final String fqcn, final Level level, final Marker marker, final String message) {
if (isEnabled(level, marker, message)) {
logMessage(fqcn, level, marker, message);
}
}
上面的这段代码很清晰的描述了log4j2的架构，如果当前打印的日志级别满足logger配置的要求则进入到logMessage中进行操作。来看一下isEnabled是如何实现的，
@Override
public boolean isEnabled(final Level level, final Marker marker, final String message) {
return privateConfig.filter(level, marker, message);
}
boolean filter(final Level level, final Marker marker, final String msg) {
final Filter filter = config.getFilter();
if (filter != null) {
final Filter.Result r = filter.filter(logger, level, marker, msg);
if (r != Filter.Result.NEUTRAL) {
return r == Filter.Result.ACCEPT;
}
}
return level != null && intLevel >= level.intLevel();
}
上面的filter函数主要分为两个逻辑，
- 获取配置的filter，如果filter的过滤结果是Filter.Result.ACCEPT, 那么认为该日志可以打印。
- 否则进行默认的判断，当且仅当logger的默认级别大于等于当前打印的级别的时候才认为该日志可以打印。
也就是说如果按照第二种方法进行配置的话，实际上log4j2认为该日志是可以打印的，也就是filter函数返回的是true。那么就会进入到logMessage方法中，而如果采用第一种方法则会直接跳出if语句，不会调用logMessage。由此可以看出第二种方法会比第一种方法多耗时在logMessage的调用上。
为什么第二种方法虽然耗时较长，但是也可以达到目的呢？继续看一下logMessage的实现，代码定位到LoggerConfig的callAppenders方法中，
@PerformanceSensitive("allocation")
protected void callAppenders(final LogEvent event) {
final AppenderControl[] controls = appenders.get();
//noinspection ForLoopReplaceableByForEach
for (int i = 0; i < controls.length; i++) {
controls[i].callAppender(event);
}
}
上面的代码会获取logger配置的所有appender，并且遍历所有appender将logevent交给appender处理。
public void callAppender(final LogEvent event) {
if (shouldSkip(event)) {
return;
}
callAppenderPreventRecursion(event);
}
private boolean shouldSkip(final LogEvent event) {
return isFilteredByAppenderControl(event) || isFilteredByLevel(event) || isRecursiveCall();
}
关键的地方在于isFilteredByLevel函数的调用，
@PerformanceSensitive
private boolean isFilteredByLevel(final LogEvent event) {
return level != null && intLevel < event.getLevel().intLevel();
}
由于第二种方法配置的appender的level都是高于debug的，所以isFilteredByLevel返回的都是true，从而导致shouldSkip也返回true，后面实际的调用步骤就走不到了，这也就是为什么第二种方法也能达到目的原因。
既然上面提到了第二种性能会差一些，那么我们实际来做一个测试。测试代码如下，
package hello;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.boot.*;
import org.springframework.boot.autoconfigure.*;
import org.springframework.stereotype.*;
import org.springframework.web.bind.annotation.*;
@Controller
@EnableAutoConfiguration
public class SampleController {
public static Logger LOGGER = LoggerFactory.getLogger(SampleController.class);
@RequestMapping("/")
@ResponseBody
String home() {
long start = System.currentTimeMillis();
for (int i = 0; i < 1000000; i++) {
LOGGER.debug("welcome");
}
long end = System.currentTimeMillis();
LOGGER.info("cost {}", end - start);
return "welcome";
}
public static void main(String[] args) throws Exception {
SpringApplication.run(SampleController.class, args);
}
}
上面的代码在请求的时候循环100万次调用debug打印日志，采用第二种配置的时候，
<?xml version="1.0" encoding="UTF-8"?>
<configuration status="DEBUG">
<appenders>
<Console name="consolePrint" target="SYSTEM_OUT">
<PatternLayout pattern="%d{HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%n" />
</Console>
<File name="File" fileName="logs/app.log">
<PatternLayout pattern="%d{HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%n" />
</File>
</appenders>
<loggers>
<root level="debug">
<appender-ref ref="consolePrint" level="info"/>
<appender-ref ref="File" level="info"/>
</root>
</loggers>
</configuration>
连续调用五次的结果如下，
01:45:40.624 [http-nio-8080-exec-1] INFO hello.SampleController - cost 221
01:45:48.300 [http-nio-8080-exec-3] INFO hello.SampleController - cost 179
01:45:50.527 [http-nio-8080-exec-4] INFO hello.SampleController - cost 169
01:45:52.468 [http-nio-8080-exec-5] INFO hello.SampleController - cost 178
01:45:54.069 [http-nio-8080-exec-6] INFO hello.SampleController - cost 172
当采用第一种配置的时候，将
01:51:35.248 [http-nio-8080-exec-1] INFO hello.SampleController - cost 17
01:51:36.886 [http-nio-8080-exec-3] INFO hello.SampleController - cost 10
01:51:38.210 [http-nio-8080-exec-5] INFO hello.SampleController - cost 4
01:51:39.169 [http-nio-8080-exec-7] INFO hello.SampleController - cost 4
01:51:40.232 [http-nio-8080-exec-9] INFO hello.SampleController - cost 3
很明显第一种性能要高于第二种，虽然平均到单次的时间差别基本上可以忽略不计。但是由于第二种方式明显违反了框架最初的设计意愿，所以还是第一种方法更好，并且更容易让他人明白。