到底该不该写isDebugEnabled

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

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

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 filter 文章

logback.qos.ch/manual/filt…

is判断的必要性

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

是的

源码解析

  1. public boolean isDebugEnabled(Marker marker) {
  2. FilterReply decision = this.callTurboFilters(marker, Level.DEBUG);
  3. if (decision == FilterReply.NEUTRAL) {
  4. return this.effectiveLevelInt <= 10000;
  5. } else if (decision == FilterReply.DENY) {
  6. return false;
  7. } else if (decision == FilterReply.ACCEPT) {
  8. return true;
  9. } else {
  10. throw new IllegalStateException("Unknown FilterReply value: " + decision);
  11. }
  12. }
  13. //如果系统可以打印 debug,输出 FilterReply.NEUTRAL,如果不能,输出FilterReply.DENY
  14. private FilterReply callTurboFilters(Marker marker, Level level) {
  15. return this.loggerContext.getTurboFilterChainDecision_0_3OrMore(marker, this, level, (String)null, (Object[])null, (Throwable)null);
  16. }
  17. 复制代码

可以看到,经过一些判断,最终调用到了getTurboFilterChainDecision_0_3OrMore方法,再看debug代码

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

debug 也是执行了 getTurboFilterChainDecision_0_3OrMore

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

小总结

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

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

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

准备工具

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

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

测试场景

看黄色的线

代码

  1. private static final Integer count = 100;
  2. @GetMapping("/testDebug")
  3. public String testDebug() {
  4. for (int i = 0; i < count; i++) {
  5. log.debug(new B() + "3" + "4");//就算设置了不打印debug,也会执行内容的拼接,会影响性能
  6. }
  7. return "success";
  8. }
  9. @GetMapping("/testDebugForEnabled")
  10. public String testDebugForEnabled() {
  11. for (int i = 0; i < count; i++) {
  12. if(log.isDebugEnabled()){
  13. log.debug(new byte[1024 * 1024] + "3" + "4");//就算设置了不打印debug,也会执行内容的拼接,会影响性能
  14. }
  15. }
  16. return "success";
  17. }
  18. public class B {
  19. private byte[] b = new byte[1024 * 1024];
  20. public B() {
  21. System.out.println("B的初始化");
  22. }
  23. }
  24. 复制代码

系统打印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代码

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

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

彩蛋

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

format_png 7

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

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

这里就有2个点

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

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

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

比如

  1. public final class Level implements java.io.Serializable {
  2. private static final long serialVersionUID = -814092767334282137L;
  3. public static final int OFF_INT = Integer.MAX_VALUE;
  4. public static final int ERROR_INT = 40000;
  5. public static final int WARN_INT = 30000;
  6. public static final int INFO_INT = 20000;
  7. public static final int DEBUG_INT = 10000;
  8. public static final int TRACE_INT = 5000;
  9. public static final int ALL_INT = Integer.MIN_VALUE;
  10. }
  11. 复制代码

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

想到Rocketmq 也有类似的

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

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

我们首先要看

  1. public enum FilterReply {
  2. DENY, NEUTRAL, ACCEPT;
  3. }
  4. 复制代码

分别代表着

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

    public boolean isDebugEnabled(Marker marker) {

    1. final FilterReply decision = callTurboFilters(marker, Level.DEBUG);
    2. //如果是中性 就需要进行后续判断
    3. if (decision == FilterReply.NEUTRAL) {
    4. return effectiveLevelInt <= Level.DEBUG_INT;
    5. } else if (decision == FilterReply.DENY) {
    6. //如果是拒绝 执行返回false,不用打印了
    7. return false;
    8. } else if (decision == FilterReply.ACCEPT) {
    9. //如果是统一 执行返回true,需要打印
    10. return true;
    11. } else {
    12. throw new IllegalStateException("Unknown FilterReply value: " + decision);
    13. }

    }
    复制代码

分开分析

中性

又说回到 getTurboFilterChainDecision_0_3OrMore 方法了

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

第一步判断 turboFilterList 是否为空

turboFilterList 是哪里初始化的呢?

format_png 8

只找到了这个,debug一下

LoggingSystem的实例化

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

  1. //源自package org.springframework.boot.logging;
  2. public abstract class LoggingSystem {
  3. static {
  4. Map<String, String> systems = new LinkedHashMap<>();
  5. systems.put("ch.qos.logback.core.Appender",
  6. "org.springframework.boot.logging.logback.LogbackLoggingSystem");
  7. systems.put("org.apache.logging.log4j.core.impl.Log4jContextFactory",
  8. "org.springframework.boot.logging.log4j2.Log4J2LoggingSystem");
  9. systems.put("java.util.logging.LogManager",
  10. "org.springframework.boot.logging.java.JavaLoggingSystem");
  11. SYSTEMS = Collections.unmodifiableMap(systems);
  12. }
  13. public static LoggingSystem get(ClassLoader classLoader) {
  14. String loggingSystem = System.getProperty(SYSTEM_PROPERTY);
  15. if (StringUtils.hasLength(loggingSystem)) {//你也通过org.springframework.boot.logging.LoggingSystem来特殊指定
  16. if (NONE.equals(loggingSystem)) {
  17. return new NoOpLoggingSystem();
  18. }
  19. return get(classLoader, loggingSystem);
  20. }
  21. return SYSTEMS.entrySet().stream()
  22. .filter((entry) -> ClassUtils.isPresent(entry.getKey(), classLoader))
  23. .map((entry) -> get(classLoader, entry.getValue())).findFirst()
  24. .orElseThrow(() -> new IllegalStateException(
  25. "No suitable logging system located"));//取第一个
  26. }
  27. }
  28. 复制代码

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

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

说那么多没什么用,应该怎么用呢?

删除了多余的东西(logback.xml)

  1. <appender name="INFO-APPENDER" class="ch.qos.logback.core.rolling.RollingFileAppender">
  2. <!-- 过滤器,记录info级别以上的日志 -->
  3. <filter class="com.xxx.demo.springboot.test.C">
  4. </filter>
  5. </appender>
  6. 复制代码

启动之后给我报错

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

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

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

后面换成

  1. @Component
  2. public class C extends AbstractMatcherFilter<ILoggingEvent> {
  3. @Override
  4. public FilterReply decide(ILoggingEvent iLoggingEvent) {
  5. return FilterReply.ACCEPT;
  6. }
  7. }
  8. 复制代码

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

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

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

format_png 9

spi的加载 前面还是native

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

细节可以看 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

发表评论

表情:
评论列表 (有 0 条评论,79人围观)

还没有评论,来说两句吧...

相关阅读

    相关 到底使用Python?

    最近,大家总在吐槽Python:“虽然它是一种不错的语言,但不适用于专业领域。” 前不久,我在LinkedIn上找到一篇帖子,主要建议初级开发人员应该学习哪种语言,以便获得更

    相关 到底办网呢???

    最近一直在考虑一个问题,该不该办宽带,我是个爱玩的人,要是再办了网我真怕自己整天上网玩了。。。![Image 1][] 但是又一想,办上网之后学习也能方便得多了呀。可以随时上