动态日志级别：小功能，大用处

⚠️本文为掘金社区首发签约文章，未获授权禁止转载

Log4j，Log4j2，Logback是当下主流的日志框架，Slf4j则是新一代的日志框架接口，其中Logback直接实现了Slf4j的接口，同时它也是SpringBoot的默认日志框架。

但从性能以及工程的角度上来看，Log4j2是事实标准，本文也是基于Log4j2来撰写的。

为什么需要动态日志级别

关于Log4j2的名词小知识：

• 配置方式：工业级项目一般都采用XML的配置方式
• 同步/异步：Log4j2支持同步/异步日志两种方式，如无特殊的场景需要，建议采用高性能的异步方式
• Logger：Logger节点是用来单独指定日志的表现形式配置项，包括但不限于：日志级别、关联Appender、Name属性等
• Appender：Appender通常只负责将事件数据写入目标目标目标，由Logger触发指定的Appender执行。

作为一个合格的程序员，大家对于日志的重要性以及日志框架的基本使用方法都了然于心。

在绝大多数时候，日志都是帮助我们定位问题的利器，但所有事物都有两面性，有时它也会成为问题的导火索。

接口莫名其妙变慢？

一般来说，接口的响应时间基本都花在网络、DB层、IO层或者部分计算上，但我某一次排查B端线上问题时，竟然发现是由于打印日志拖垮了整个接口。

由于老系统的某个业务异常处理不合理，导致有大量的错误日志输出，进而造成当前线程阻塞，机器负载升高，整个接口的吞吐量降低。

定义这种莫名其妙的问题倒也简单：

1. 查看机器磁盘是否异常（磁盘占用、文件大小）
2. 通过Jstack命令检查占用较高的线程
3. 观察日志输出情况（异常情况下非常明显）

PS：当时的处理方案是优化了日志输出，同时将同步日志调整为异步日志

线上CPU飙赠

我们在看日志时都希望准确，干净，可复制至其他工具进行分析，所以日志一般都会这么写：

 log.info("Method :: Kerwin.Demo, Params: {}, Result:{}", JSONUtil.toJsonStr(demo), JSONUtil.toJsonStr(demo));
复制代码

这就涉及到了序列化操作，当此类日志数量较多，接口调用次数较高时（每分钟几十万的C端调用），CPU占用就会非常明显的升高，即使整个程序没有任何问题。

所以我们需要使用日志框架的动态化调整日志级别的能力，这样一来我们在编码阶段所留下的日志也不需要在上线前删除了，同时可以更灵活的应对线上问题的排查和日常使用。

如何动态配置日志级别

以Log4j2为例，我们可能会这样配置根节点（ROOT Logger）

<Loggers>
    <AsyncRoot level="ERROR" includeLocation="true">
        <AppenderRef ref="INFO_LOG"/>
        <AppenderRef ref="ERROR_LOG"/>
    </AsyncRoot>
</Loggers>
复制代码

使用以下代码，并查看日志文件

@Slf4j
public class LogTest {
    public static void main(String[] args) {
        log.info("This is a Demo...");
    }
}
复制代码

因为我调整ROOT的日志级别为ERROR，因此无任何日志输出

利用Log4j2提供的能力，修改日志级别，如下所示：

@Slf4j
public class LogTest {
    public static void main(String[] args) {
        log.info("This is a Demo... 111");
        Level level = Level.toLevel("info");
        LoggerContext context = (LoggerContext) LogManager.getContext(false);
        Configuration configuration = context.getConfiguration();
        configuration.getLoggerConfig("ROOT").setLevel(level);
        context.updateLoggers(configuration);
        log.info("This is a Demo... 222");
    }
}
复制代码

结果如下所示：

非常容易的实现了修改日志级别的能力，因此我们在构建自己的应用或者系统时，可以使用ZK进行动态化配置，也可以使用HTTP或RPC接口留一个后门，以此来实现动态调整的能力。

如何配置指定类的日志级别

上面的代码演示了如何动态配置ROOT Logger节点，如果您在阅读本文时能使用IDE，自然能看到

org.apache.logging.log4j.core.config.Configuration#getLoggers，该方法包括了每一个自定义logger的配置参数，同样可以使用上述方式进行配置和修改。

代码范例：

String packetLoggerName = "log.demo";
Level level = Level.toLevel("DEBUG");
LoggerContext context = (LoggerContext) LogManager.getContext(false);
Configuration configuration = context.getConfiguration();
for (Map.Entry<String, LoggerConfig> entry : configuration.getLoggers().entrySet()) {
    if (packetLoggerName.equals(entry.getKey())) {
        entry.getValue().setLevel(level);
    }
}

context.updateLoggers(configuration);
复制代码

下图则是我们的日志级别配置：

疑问：框架如何处理没有Logger的类

先说结论：

1. 每一个Logger不一定都有其对应的配置
2. 实际工作的Logger并不一定是其本身，如上文中的：log.demo.test.LogTestApp
3. Logger之间具有继承性，即log.demo.test.LogTestApp在不作其他额外配置的情况下，会使用父级配置：log.demo，以此类推直到ROOT

使用以下配置及代码，即可进行验证：

 <Loggers>
     <AsyncRoot level="INFO" includeLocation="true">
         <AppenderRef ref="Console"/>
     </AsyncRoot>

     <logger name="log.demo" level="ERROR">
         <AppenderRef ref="ERROR_LOG"/>
     </logger>
</Loggers>
复制代码

@Slf4j
public class LogTestApp {
    public static void main(String[] args) {
        System.out.println(log.getName());
    }
}

// 输出结果
// log.demo.test.LogTestApp
复制代码

通过观察配置文件，我们可以很明显的发现，整个日志框架实际上是不存在：log.demo.test.LogTestApp 这个Logger的，那它到底是如何工作的呢？

核心代码分析如下：

private static final Logger log = LoggerFactory.getLogger(LogTestApp.class);
复制代码

通过工厂的方式创建一路跟源码，可以发现类：AbstractConfiguration

@Override
public LoggerConfig getLoggerConfig(final String loggerName) {
    LoggerConfig loggerConfig = loggerConfigs.get(loggerName);
    if (loggerConfig != null) {
        return loggerConfig;
    }
    String substr = loggerName;
    while ((substr = NameUtil.getSubName(substr)) != null) {
        loggerConfig = loggerConfigs.get(substr);
        if (loggerConfig != null) {
            return loggerConfig;
        }
    }
    return root;
}
复制代码

该方法的作用就是给每一个类的Logger绑定实际的执行者，其中NameUtil.getSubName()方法即获取当前类的全路径的上一层，通过循环遍历找到最近（所谓最近即以包名为界限，由子向父级递推）的Logger。

了解完以上的特性，我们也就有了问题的答案。

按需配置父级Logger

随着工程化的推进，系统代码的层次性非常明显，以我司为例，主要分为：Dao、Service、Business、Api这四层，其中核心业务一般都放在Business层，所以在一般情况下出问题也都发生Business层，我们可以配置以下Logger，动态调整所有的Business的日志级别，以达到更加精准的控制：

<Loggers>
    <logger name="com.jd.o2o.business" level="INFO">
        <!-- INFO_LOG -->
    </logger>
</Loggers>
复制代码

同理，如果需要关注DB层的话，也可以配置父级Logger来监控DB层的日志。

动态生成Logger

其实从上文中动态调整日志级别就可以发现一些端倪，既然日志框架支持动态刷新配置，那么它一定支持动态新增配置（即使当前版本不支持，也只是尚未开发）。

通过阅读源码，可以看出以下方法可以满足我们的要求：

org.apache.logging.log4j.core.config.Configuration#addLogger

PS：个人不建议使用该种方式，因为编码相对繁琐，且过于灵活反而导致问题不好排查

疑问：莫名其妙的输出

有时候我们也会遇到这种问题：某一个Logger我想让它打ERROR日志，只输出到ERROR文件，结果它输出到了INFO、ERROR，这是为什么？

这其实是日志框架的设计问题，核心代码如下所示：

private void processLogEvent(final LogEvent event, final LoggerConfigPredicate predicate) {
    event.setIncludeLocation(isIncludeLocation());
    if (predicate.allow(this)) {
    	callAppenders(event);
    }
    logParent(event, predicate);
}
复制代码

日志事件在打印时，会传递给所有的Appenders，最后它还会向父级Logger传递日志事件，这也就导致我们明明只配置了ERROR，结果却输出到了INFO和ERROR。

观察如下代码即可找到解决办法：

// 核心代码
private void logParent(final LogEvent event, final LoggerConfigPredicate predicate) {
    if (additive && parent != null) {
        parent.log(event, predicate);
    }
}

// 解决办法 additivity置为false
<logger name="log.demo" level="INFO" additivity="false"></logger>
复制代码

打印日志的小技巧

在日志使用中除了正确的打印之外也存在一些小Tips，比如：

• 方案一：

  log.info("This is a Demo, Request:{}", JSONUtil.toJsonStr(new LogTest()));
  复制代码

• 方案二：

  if (log.isInfoEnabled()) {
      log.info("This is a Demo, Request:{}", JSONUtil.toJsonStr(new LogTest()));
  }
  复制代码

以上两种方式你会选择哪一种呢？其实对比就能看出来，一定会选择方案二，因为它可以避免不必要的序列化。

总结

大部分时间日志都是程序员的好朋友，但一些微妙的情况它反而会成为致命的风险，所以我们需要熟悉它的配置，了解它的原理。

那么如何用好日志框架呢，下面是几点建议：

1. 使用Slf4j的进行桥接，避免直接使用某一个特定日志框架
2. 合理设置RootLogger及其子Logger，可以将系统依赖的框架级日志分别输出至指定的文件中，便于问题的排查
3. 合理利用动态日志级别的能力，随时调整线上日志级别
4. 减少日志中的序列化行为，在使用低级别日志时需要判断当前日志级别是否开启，避免不必要的序列化
5. 如无特殊场景要求，尽量使用高吞吐的异步日志

如果觉得这篇内容对你有帮助的话：

1. 当然要点赞支持一下啦~
2. 另外，可以搜索并关注公众号「是Kerwin啊」，一起在技术的路上走下去吧~ ?