到底该不该写isDebugEnabled

╰半夏微凉° 2023-10-03 23:12 7阅读 0赞

## 序 ##

今天又是还愿的一天，今天的计划 提前完成，想起之前评论区的一句话

[juejin.cn/post/716304…][juejin.cn_post_716304]

![format_png][]

这里解答下

## 前提简介 ##

![format_png 1][]

`彩蛋在后面`

## 目录 ##

![format_png 2][]

## 链接 ##

logback jira地址

[\[LOGBACK-1711\] Deadlock when using Virtual Threads - QOS.ch JIRA][LOGBACK-1711_ Deadlock when using Virtual Threads - QOS.ch JIRA]

logback filter 文章

[logback.qos.ch/manual/filt…][logback.qos.ch_manual_filt]

## is判断的必要性 ##

### 即使不写is判断，debug也会对是否可以输出日志 进行判断 ###

是的

#### 源码解析 ####

public boolean isDebugEnabled(Marker marker) {
        FilterReply decision = this.callTurboFilters(marker, Level.DEBUG);
        if (decision == FilterReply.NEUTRAL) {
            return this.effectiveLevelInt <= 10000;
        } else if (decision == FilterReply.DENY) {
            return false;
        } else if (decision == FilterReply.ACCEPT) {
            return true;
        } else {
            throw new IllegalStateException("Unknown FilterReply value: " + decision);
        }
    }
    //如果系统可以打印 debug，输出 FilterReply.NEUTRAL，如果不能，输出FilterReply.DENY
    private FilterReply callTurboFilters(Marker marker, Level level) {
        return this.loggerContext.getTurboFilterChainDecision_0_3OrMore(marker, this, level, (String)null, (Object[])null, (Throwable)null);
    }
    复制代码

可以看到，经过一些判断，最终调用到了getTurboFilterChainDecision\_0\_3OrMore方法，再看debug代码

public void debug(String msg) {
        this.filterAndLog_0_Or3Plus(FQCN, (Marker)null, Level.DEBUG, msg, (Object[])null, (Throwable)null);
    }
    
    private void filterAndLog_0_Or3Plus(String localFQCN, Marker marker, Level level, String msg, Object[] params, Throwable t) {
        FilterReply decision = this.loggerContext.getTurboFilterChainDecision_0_3OrMore(marker, this, level, msg, params, t);
        if (decision == FilterReply.NEUTRAL) {
            if (this.effectiveLevelInt > level.levelInt) {
                return;
            }
        } else if (decision == FilterReply.DENY) {
            return;
        }
        //如果是 占位符 只有通过前面的判断才会执行到这,所以不会有拼接的性能问题
        this.buildLoggingEventAndAppend(localFQCN, marker, level, msg, params, t);
    }
    
    
    public void debug(String format, Object arg) {
        this.filterAndLog_1(FQCN, (Marker)null, Level.DEBUG, format, arg, (Throwable)null);
    }
    复制代码

debug 也是执行了 getTurboFilterChainDecision\_0\_3OrMore

如果是 占位符 只有通过前面的判断才会执行到这,所以不会有**拼接**的性能问题，但是如果**这个属性创建的内存消耗**

#### 小总结 ####

不写is判断，输出日志的时候 也会判断

**从这个角度 isDebugEnabled是可以不写的**

## 即便系统不打印debug，新创建的对象也占用内存 ##

### 准备工具 ###

先要能验证 内存是否占用了，使用哪个工具呢？

也不用看到字节程度，直接多执行一些次数，然后看内存的差距就可以 用 **java VisualVM**

### 测试场景 ###

`看黄色的线`

#### 代码 ####

private static final Integer count = 100;
    @GetMapping("/testDebug")
    public String testDebug() {
        for (int i = 0; i < count; i++) {
            log.debug(new B() + "3" + "4");//就算设置了不打印debug，也会执行内容的拼接，会影响性能
        }
    
        return "success";
    }
    
    
    @GetMapping("/testDebugForEnabled")
    public String testDebugForEnabled() {
    
        for (int i = 0; i < count; i++) {
            if(log.isDebugEnabled()){
    
                log.debug(new byte[1024 * 1024] + "3" + "4");//就算设置了不打印debug，也会执行内容的拼接，会影响性能
            }
        }
        return "success";
    }
    
    public class B {
    
        private byte[] b = new byte[1024 * 1024];
        public B() {
            System.out.println("B的初始化");
        }
    }
    复制代码

#### 系统打印debug, 无 isDebugEnabled ####

![format_png 3][]

#### 系统打印debug，有 isDebugEnabled ####

![format_png 4][]

#### 系统不打印debug, 无 isDebugEnabled ####

![format_png 5][]

`无论系统打不打印debug，如果没有isDebugEnabled 都会创建对象，占用内存`

#### 系统不打印debug，有 isDebugEnabled ####

![format_png 6][]

#### 小总结 ####

从上面的简单测试，可以得出

`无论系统打不打印debug，如果没有isDebugEnabled 都会创建对象，占用内存`

还是需要使用isDebugEnabled的，能节省内存的消耗

`虽然我们平时工作中一般都是debug日志 上生产会关闭，而且 一般日志打印的也都是一些现成的对象，而不是新建的对象，但是 还是推荐添加 isDebugEnabled`

## 额外问题 ##

### 之前为什么会有需要写is 判断呢？ ###

在N久以前，很多日志框架都不支持\{\}模板的写法(如Log4j1.X, Apache Commons Logging)，于是只能通过字符串拼接来输出日志内容：

log.debug("hello, this is " + name);

这样一来，每当JVM执行到此时，不管你当前的日志级别是多少，都会执行一次字符串拼接，然后将结果做为形参传递给debug()方法，这样就带来了无用的性能损耗。这时，提前判断isDebugEnabled()可以解决此问题

if (log.isDebugEnabled()) \{ log.debug("hello, this is " + name); \}

这样写的好处有二：

当日志级别在DEBUG以下时，log.debug("hello, this is " + name)就不会执行，从而没有字符串拼接的开销。 JIT在运行时会优化if语句，如果isDebugEnabled()返回false, 则JIT会将整个if块全部去掉。

### 使用占位符 能解决String 拼接的消耗？ ###

能

看debug代码

如果是 占位符 只有通过前面的判断才会执行到这,所以不会有**拼接**的性能问题，但是如果**这个属性创建的内存消耗**

## 彩蛋 ##

为了写这篇文章，把代码下载下来

![format_png 7][]

### 怎么判断 每个日志 是否应该输出 ###

其实我们很多的就是 配置 包括info 以及以上的 日志输出

这里就有2个点

1.  系统配置的info 以上才能打印，这个是哪个参数管理的
2.  有的时候 我们在 application.yml文件中会指定哪几个包下的日志打印，又是怎么回事？

#### 系统配置的info 以上才能打印，这个是哪个参数管理的 ####

首先 如果这个让我们自己实现，我们肯定也是 int标识，把优先级排序

比如

public final class Level implements java.io.Serializable {
    
        private static final long serialVersionUID = -814092767334282137L;
    
        public static final int OFF_INT = Integer.MAX_VALUE;
        public static final int ERROR_INT = 40000;
        public static final int WARN_INT = 30000;
        public static final int INFO_INT = 20000;
        public static final int DEBUG_INT = 10000;
        public static final int TRACE_INT = 5000;
        public static final int ALL_INT = Integer.MIN_VALUE;
        
    }
    复制代码

这个没毛病，举一反三，我们还会在哪这么使用

想到`Rocketmq` 也有类似的

public class MQVersion {
        //这里ordinal 也是把版本号 变为int 进行比较
        public static final int CURRENT_VERSION = Version.V4_9_3.ordinal();
        
    }
    复制代码

好，我们继续，说到这，日志打不打印又是哪里控制的？

我们首先要看

public enum FilterReply {
        DENY, NEUTRAL, ACCEPT;
    }
    复制代码

分别代表着

1.  DENY 拒绝
2.  NEUTRAL 中性
3.  ACCEPT 同意

public boolean isDebugEnabled(Marker marker) {
        final FilterReply decision = callTurboFilters(marker, Level.DEBUG);
        //如果是中性 就需要进行后续判断
        if (decision == FilterReply.NEUTRAL) {
            return effectiveLevelInt <= Level.DEBUG_INT;
        } else if (decision == FilterReply.DENY) {
           //如果是拒绝 执行返回false，不用打印了
            return false;
        } else if (decision == FilterReply.ACCEPT) {
           //如果是统一 执行返回true，需要打印
            return true;
        } else {
            throw new IllegalStateException("Unknown FilterReply value: " + decision);
        }
    }
    复制代码

分开分析

#### 中性 ####

又说回到 getTurboFilterChainDecision\_0\_3OrMore 方法了

final FilterReply getTurboFilterChainDecision_0_3OrMore(final Marker marker, final Logger logger, final Level level,
            final String format, final Object[] params, final Throwable t) {
        if (turboFilterList.size() == 0) {
            return FilterReply.NEUTRAL;
        }
        return turboFilterList.getTurboFilterChainDecision(marker, logger, level, format, params, t);
    }
    复制代码

第一步判断 turboFilterList 是否为空

turboFilterList 是哪里初始化的呢？

![format_png 8][]

只找到了这个，debug一下

**LoggingSystem的实例化**

`LoggingSystem`被实例化那个，默认它取得顺序是`LogbackLoggingSystem`>`Log4J2LoggingSystem`>`JavaLoggingSystem`，如果类存在就选择。

//源自package org.springframework.boot.logging;
    public abstract class LoggingSystem {
    	static {
    		Map<String, String> systems = new LinkedHashMap<>();
    		systems.put("ch.qos.logback.core.Appender",
    				"org.springframework.boot.logging.logback.LogbackLoggingSystem");
    		systems.put("org.apache.logging.log4j.core.impl.Log4jContextFactory",
    				"org.springframework.boot.logging.log4j2.Log4J2LoggingSystem");
    		systems.put("java.util.logging.LogManager",
    				"org.springframework.boot.logging.java.JavaLoggingSystem");
    		SYSTEMS = Collections.unmodifiableMap(systems);
    	}
    	public static LoggingSystem get(ClassLoader classLoader) {
    		String loggingSystem = System.getProperty(SYSTEM_PROPERTY);
    		if (StringUtils.hasLength(loggingSystem)) {//你也通过org.springframework.boot.logging.LoggingSystem来特殊指定
    			if (NONE.equals(loggingSystem)) {
    				return new NoOpLoggingSystem();
    			}
    			return get(classLoader, loggingSystem);
    		}
    		return SYSTEMS.entrySet().stream()
    				.filter((entry) -> ClassUtils.isPresent(entry.getKey(), classLoader))
    				.map((entry) -> get(classLoader, entry.getValue())).findFirst()
    				.orElseThrow(() -> new IllegalStateException(
    						"No suitable logging system located"));//取第一个
    	}    
    }    
    复制代码

这个其实就是 如果 有turboFilterList 数组，就开始 for循环处理，直到返回 FilterReply

for(int i = 0; i < len; ++i) {
        TurboFilter tf = (TurboFilter)tfa[i];
        FilterReply r = tf.decide(marker, logger, level, format, params, t);
        if (r == FilterReply.DENY || r == FilterReply.ACCEPT) {
            return r;
        }
    }
    复制代码

说那么多没什么用，应该怎么用呢？

删除了多余的东西（logback.xml）

<appender name="INFO-APPENDER" class="ch.qos.logback.core.rolling.RollingFileAppender">
        
        <filter class="com.xxx.demo.springboot.test.C">
    
        </filter>
       
    </appender>
    复制代码

启动之后给我报错

ERROR in ch.qos.logback.core.joran.util.PropertySetter@f6efaab - "com.xxx.demo.springboot.test.C" was loaded by [sun.misc.Launcher$AppClassLoader@18b4aac2].
    	at org.springframework.boot.logging.logback.LogbackLoggingSystem.loadConfiguration(LogbackLoggingSystem.java:166)
    
    复制代码

这就要说到 ClassLoader 的加载机制 这是因为

@Component
    public class C extends TurboFilter {
        @Override
        public FilterReply decide(Marker marker, Logger logger, Level level, String s, Object[] objects, Throwable throwable) {
            return FilterReply.ACCEPT;
        }
    }
    复制代码

后面换成

@Component
    public class C   extends AbstractMatcherFilter<ILoggingEvent> {
    
    
        @Override
        public FilterReply decide(ILoggingEvent iLoggingEvent) {
            return FilterReply.ACCEPT;
        }
    }
    复制代码

就好了，这个时候 你可能要问

不对啊，人家调用的时候 明明代码里是 转换成TurboFilter 执行的，我不是直接实现TurboFilter 就可以了么？

还真不是，这个里面还涉及一个加载的事

![format_png 9][]

spi的加载 前面还是native

这里直接给结论，如果有兴趣可以后面写一篇

细节可以看 [logback.qos.ch/manual/filt…][logback.qos.ch_manual_filt]

这就需要说到 **Filter和TurboFilter 区别**

1.  TurboFilter对象绑定到日志上下文。因此，它们不仅在使用给定的追加器时被调用，而且在每次发出日志记录请求时都被调用。它们的范围比附加过滤器更广。
2.  它们在LoggingEvent对象创建之前被调用。TurboFilter对象不需要实例化日志事件来过滤日志请求。因此，turbo 过滤器用于高性能地过滤日志事件，甚至在事件创建之前。

其实就一句话 **turbo在事件创建之前，不是一个功能**

其实还没写完，但是真的累了。。。

![format_png 10][]

有机会继续补全。。。。

## 总结 ##

一句话 我认为 isDebugEnabled 还是要写的

**java-tools** Idea 插件 在完善，满足一些开发中使用的功能，写篇文章真的累 不行，我要去吃口饭了

![format_png 11][]

作者：雨夜之寂  
原文链接：https://juejin.cn/post/7176087632215015461

[juejin.cn_post_716304]: https://juejin.cn/post/7163045409886044168
[format_png]: https://img-blog.csdnimg.cn/img_convert/2a7c01a0ffba31e2871c8baeb64a74ec.webp?x-oss-process=image/format,png
[format_png 1]: https://img-blog.csdnimg.cn/img_convert/e31561d1b27a2a874dd495e487e40fc7.webp?x-oss-process=image/format,png
[format_png 2]: https://img-blog.csdnimg.cn/img_convert/a2c21a55c5841c93638f71a25d8047aa.webp?x-oss-process=image/format,png
[LOGBACK-1711_ Deadlock when using Virtual Threads - QOS.ch JIRA]: https://link.juejin.cn?target=https%3A%2F%2Fjira.qos.ch%2Fprojects%2FLOGBACK%2Fissues%2FLOGBACK-1711%3Ffilter%3Dallopenissues
[logback.qos.ch_manual_filt]: https://link.juejin.cn?target=https%3A%2F%2Flogback.qos.ch%2Fmanual%2Ffilters.html
[format_png 3]: https://img-blog.csdnimg.cn/img_convert/c2a68b3eb0e0b11b386806db1d02c3d7.webp?x-oss-process=image/format,png
[format_png 4]: https://img-blog.csdnimg.cn/img_convert/423e2b9047d1ca3708b10be2709718d3.webp?x-oss-process=image/format,png
[format_png 5]: https://img-blog.csdnimg.cn/img_convert/93b991497e12fff50a2ad6f5d81cc909.webp?x-oss-process=image/format,png
[format_png 6]: https://img-blog.csdnimg.cn/img_convert/bc75dd4c436c7fdeac296417128b44b6.webp?x-oss-process=image/format,png
[format_png 7]: https://img-blog.csdnimg.cn/img_convert/f195752600707cc65ae883064de41737.webp?x-oss-process=image/format,png
[format_png 8]: https://img-blog.csdnimg.cn/img_convert/0d4ec9d61282a5fb5512ae89445dba77.webp?x-oss-process=image/format,png
[format_png 9]: https://img-blog.csdnimg.cn/img_convert/1932be7815433a5c32802479a1cc5630.webp?x-oss-process=image/format,png
[format_png 10]: https://img-blog.csdnimg.cn/img_convert/cab94454501ab669cc3a4c614292d975.webp?x-oss-process=image/format,png
[format_png 11]: https://img-blog.csdnimg.cn/img_convert/ae4c1f41a1919c1bf3fc7126c76e9812.webp?x-oss-process=image/format,png