java log is判断引发的一系列事件解析

时间:2022-11-08 雨夜之寂人气:0

序

首先来源是老大code Review的时候说到日志，让我从 log.debug 加上一个if 判断，log.isDebug ，这一听就想到是为了防止debug 日志不打印，导致的String拼接等没必要的损耗

嗯嗯老大说的确实有道理，改吧

我靠，这一查几百个 log 需要加，这一个一个改也太累了

总需求列表

log 自动加上if判断如果外面有if判断了，忽略
最后写了个idea 插件。。。。

log 自动加上if判断调研

刚上来，我先百度下是不是有现成的，我现在用的lombok，按道理应该有一个属性控制是否加if的，嗯嗯没错，找找，我一般先看看 @Sl4J 给我提供了什么参数配置

@Retention( RetentionPolicy . SOURCE )
@Target({ElementType.TYPE})
public @interface Slf4j{
    String topic() default
    }

思考这个topic干什么的啊？

说实话我之前没有用过这个属性。。。。狗头。。

@Slf4j 注解有个topic 属性可以进行设置要采用的logger，
topic 的值对应的就是logback.xml中定的logger name。root logger是默认就存在的。

到这你可能要问了，root logger 是默认实现，你说是默认实现就是默认实现了？证据呢？

对应的启动Config类为 ch.qos.logback.classic.BasicConfigurator

嗯嗯根上是ROOT

有一个细节，我们在配置logback.xml的时候都会写这种

<logger name="com" level="DEBUG" >
    <appender-ref ref="STDOUT"/>
</logger>
<logger name="com.example.demo" level="warn" >
    <appender-ref ref="STDOUT"/>
</logger>

你是不是好奇这种的name怎么解析的？

他是从头开始遍历包名从loggerCache 中看看是否有匹配的，一层层找

思考

不说这些理论了，一句话按照上面配置 logback.xml 在 com.example.demo.controller 下的类执行会打印log.info日志么？

@RestController
@RequestMapping
@Slf4j
public class DemoController {
    @RequestMapping("/test")
    public String test(){
        log.info("sad");
        return "success";
    }
}

嗯嗯这么一实验没打印啊

有人可能问了，那把2个logger 顺序反过来？不用试了，也不行

这一看 com.example.demo的warn生效了啊，debug/info 都没打印出来，那为什么呢？

先看一个图

下面就要看下这个children 当时怎么赋值的了其实就是从最底下往上找，在这里找到了 com.example.demo 的配置并且应用，是因为 logger类中

int h;
do {
    h = LoggerNameUtil.getSeparatorIndexOf(name, i);
    String childName;
    if (h == -1) {
        childName = name;
    } else {
        childName = name.substring(0, h);
    }
    i = h + 1;
    synchronized(logger) {
        childLogger = logger.getChildByName(childName);
        if (childLogger == null) {
            childLogger = logger.createChildByName(childName);
            this.loggerCache.put(childName, childLogger);
            this.incSize();
        }
    }
    logger = childLogger;
} while(h != -1);

一直找到最后，返回的就是最后/最靠近目标类的logger 配置

小结

logger 配置不是按照pom.xml的那种优先顺序，而是包名匹配最多的生效，如果你发现日志打印和你想的不一样，你可以去看下 LoggerContext 类中 loggerCache 属性的值，检查下

如果是一个业务系统，可能是一种logback.xml模板，如果你是中间件/组件，就需要对logback.xml 进行改动了，因为中间件可能是 binlog监听等等大数据量的，如果按照业务系统那种搞法 有的日志是没必要，根据你的业务请自由配置

说回来 lombok 到底有没有自动加if的插件啊

lombok @Sl4j 是没有了，百度下吧

好吧，这也什么都没有，官网看看，哎也没有，按道理应该有啊，也不难。。。

我突然在想是不是这个优化也不像我们想的那么有优化效果，肯定还是有必要的

log isDebug 判断的必要性

错误案例

现象描述：发现某些服务器的pv数不高，但服务器的load却不低，高于平均水平

错误分析

分析过程：通过内存监控发现，GC的动作比较频繁，但无法找到原因，一次PLA偶然的发现了大量如log.debug(“memberId:” + member.getMemberId())代码

原因分析

在代码中发现如下代码段很多： log.debug(“memberId:” + member.getMemberId())

以上代码执行时，分两步：

先执行的是括号中的字符串相”+”的动作，而每次”+”运算都会导致新字符串的生成，这样就产生了很多“中间字符串”，在极大次数被调用时，这种字符串被创建和销毁的数量非常庞大，从而造成了jvm gc频繁执行，进而影响了性能。
再执行log.debug()函数，在生产环境log level一般大于info，所以实际不会打印debug信息综上所述，这些代码在生产环境不会产生日志，但会执行字符串”+”运算，而这些运算是无意义的，所以需要先判断日志的优先级，方式是log.isXXXEnabled() { log.XXX(……); }

Log Level的级别： Fatal->error->warn->info->debug，级别从高到低一般我们生成环境的log level都是error，所以对于Error以上级别的日志，不用判断；对于error以下级别的都要加上判断。

总结

is 判断还是有必要的，目前没什么别的办法，我在写一个idea 插件，来一个按钮/快捷键自动添加log if判断，正好玩玩

后续

行吧，既然说了做一个idea 插件，搞起来，周末花了几个小时搞了一版，提交了idea 审核，等待审核中起名叫java-tools 开发会用的功能我会迭代进去，有什么是你们需要的可以评论下，我会排下优先级开发

简单效果：

@Slf4j
public class A {
    public void a(){
        log.info("21") ;
    }
}

点击 ctrl + 8 一起按或者右键

变为

@Slf4j
public class A {
    public void a(){
        if(log. isInfoEnabled()){
        log. info("21");
        }
    }
}

加载全部内容