到底该不该写isDebugEnabled
序
今天又是还愿的一天,今天的计划 提前完成,想起之前评论区的一句话
juejin.cn/post/716304…
这里解答下
前提简介
彩蛋在后面
目录
链接
logback jira地址
[LOGBACK-1711] Deadlock when using Virtual Threads - QOS.ch JIRA
logback filter 文章
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
系统打印debug,有 isDebugEnabled
系统不打印debug, 无 isDebugEnabled
无论系统打不打印debug,如果没有isDebugEnabled 都会创建对象,占用内存
系统不打印debug,有 isDebugEnabled
小总结
从上面的简单测试,可以得出
无论系统打不打印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代码
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);
}
复制代码
如果是 占位符 只有通过前面的判断才会执行到这,所以不会有拼接的性能问题,但是如果这个属性创建的内存消耗
彩蛋
为了写这篇文章,把代码下载下来
怎么判断 每个日志 是否应该输出
其实我们很多的就是 配置 包括info 以及以上的 日志输出
这里就有2个点
- 系统配置的info 以上才能打印,这个是哪个参数管理的
- 有的时候 我们在 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;
}
复制代码
分别代表着
- DENY 拒绝
- NEUTRAL 中性
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 是哪里初始化的呢?
只找到了这个,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">
<!-- 过滤器,记录info级别以上的日志 -->
<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 就可以了么?
还真不是,这个里面还涉及一个加载的事
spi的加载 前面还是native
这里直接给结论,如果有兴趣可以后面写一篇
细节可以看 logback.qos.ch/manual/filt…
这就需要说到 Filter和TurboFilter 区别
- TurboFilter对象绑定到日志上下文。因此,它们不仅在使用给定的追加器时被调用,而且在每次发出日志记录请求时都被调用。它们的范围比附加过滤器更广。
- 它们在LoggingEvent对象创建之前被调用。TurboFilter对象不需要实例化日志事件来过滤日志请求。因此,turbo 过滤器用于高性能地过滤日志事件,甚至在事件创建之前。
其实就一句话 turbo在事件创建之前,不是一个功能
其实还没写完,但是真的累了。。。
有机会继续补全。。。。
总结
一句话 我认为 isDebugEnabled 还是要写的
java-tools Idea 插件 在完善,满足一些开发中使用的功能,写篇文章真的累 不行,我要去吃口饭了
作者:雨夜之寂
原文链接:https://juejin.cn/post/7176087632215015461
还没有评论,来说两句吧...