在Java代码中打日志需要注意什么？

Posted 2020-12-19

每周至少一篇原创技术文章
周一早上【8:50】准时推送
偶尔也会分享生活的点滴与感悟
这是本公众号的第 4 篇原创文章

为什么要打日志？

日志是什么？日志是你在代码运行时打印出来的一些数据和记录，是快速排查问题的好帮手，是撕逼和甩锅的利器！

做一件事情之前，先思考为什么。为什么我们在开发中，需要打日志？原因很简单，没人能保证自己写的程序没有BUG，即使你做了足够的测试，也只是能降低产生BUG的概率而已。

尤其是当今分布式环境，定位问题变得越来越复杂。所以我们想要获取一些程序“运行时”的信息，日志就是最方便的。

所以，这种福泽后来人的好东西，当然要用起来了~

Java日志框架

要说Java日志框架啊，要从远古时代的JDK 1.3之前说起。那时候大家打印日志就是直接输出到STDOUT或者STDERR流。

System.out.println()
System.err.println()
e.printStackTrace()

于是log4j在大牛Ceki中应运而生，后面经过一系列的发展，以及Ceki与Apache的吃瓜事件，逐渐发展为slf4j、logback、log4j2三种最主流的日志框架。

• slf4j: 日志的“门面”框架，对于用户来说只要使用SLF4J提供的接口，即可隐藏日志的具体实现。
• logback: 与slf4j一样，为Ceki大神创建，所以原生实现slf4j，Spring Boot钦点的默认日志框架。
• log4j2: Apache顶级项目，性能优于logback，尤其是异步输出，表现比较好。

?
PS: 4j是for Java的意思，在Java开源项目中是很常见的命名方式。
?

所以现在主流的框架一般是slf4j + logback或者slf4j + log4j2。

?
阿里巴巴开发手册中，日志规约第一条就是：应用中不可直接使用日志系统（Log4j、Logback）中的API，而应依赖使用日志框架（SLF4J、JCL--Jakarta Commons Logging）中的API，使用门面模式的日志框架，有利于维护和各个类的日志处理方式统一。
?

如何选择日志级别？

关于日志级别，不同的标准有不同的定义。鉴于slf4j差不多已经一统天下，所以我们主要介绍slf4j定义的5种日志级别。

5种日志级别

ERROR、WARN、INFO、DEBUG、TRACE这五个级别从高到低，「配置级别越高日志输出就越少」。

我们在配置输出某个级别的日志的时候，它也会输出比它高级别的日志。比如我们配置日志在INFO这一级别，它会输出ERROR、WARN、INFO三种级别的日志。

顾名思义，这几种级别的日志分别会输出不同程度信息：

• ERROR：错误日志，比较严重的错误，对正常业务有影响；
• WARN：警告日志，一般的错误，对业务影响不大；
• INFO：信息日志，记录一些日常的东西，比如调用时间、出参入参、业务信息等；
• DEBUG：用于DEBUG的，关键逻辑里面的运行时数据；
• TRACE：最详细的信息，一般这些信息只记录到日志文件中。

?
PS: 根据笔者的经验来看，使用TRACE级别的比较少。log4j建议只有前4个级别。
?

级别继承

有时候，我们可能根据不同的业务输出不同级别的日志。比如某些重要业务输出INFO级别，其他业务输出WARN级别的日志，同时关闭所有库、框架的日志，比如Spring等。

日志级别继承

一般情况，我们设置root级别了就行了，对于某些业务有特殊要求的话，对特定的包配置就行了。这里值得一提的是，谨慎开启低级别的日志，尤其是对root级别。之前听说过一个故障，就是为了Debug一个问题，在生产环境开启了DEBUG日志，并且是root级别，导致瞬间打印出巨量的日志，磁盘撑不住，造成了生产事故。

logging:
  level:
    org:
      springframework:
        orm: DEBUG
        transaction: DEBUG
    root: INFO

注意事项

开关判断
在阿里的Java开发手册中，有这么一条规约：

?
【强制】：对于 trace/debug/info 级别的日志输出，必须进行日志级别的开关判断。
?

也就是说，在日志级别比较低的时候，应该在打日志前增加一个判断，「减少不必要的方法调用开销」。举个例子：

// 打日志的业务代码
User user = new User(1L, "username", "pwd");
log.debug("userId is: {}", user.getId());
return user;

// user.getId()实现
public long getId() {
    System.out.println("调用了getId()");
    return id;
}

上面这段代码，我在打debug日志的时候，调用了user.getId()方法，这个时候，即使我们配置只打INFO级别的日志，运行到这段代码的时候，仍然会调用user.getId()方法，造成不必要的开销。

如果我们在前面添加一个判断就可以解决这个问题：

User user = new User(1L, "username", "pwd");
if (log.isDebugEnabled()) {
    log.debug("userId is: {}", user.getId());
}

return user;

当然，这个根据自己的项目来。「如果你的项目部署肯定会开启INFO级别的日志，那INFO级别的日志，可以不加条件判断」。

使用参数占位

在上面的例子中，我们使用了大括号{}来作为日志中的占位符。相比于使用+操作符进行字符串的拼接，使用占位符可以让我们的代码更加优雅简洁。

除此以外，String字符串的拼接会使用StringBuilder的append()方式，有一定的性能损耗。使用占位符仅是替换动作，可以有效提升性能。

日志越多越好？

日志其实也是代码中的一部分。我们都知道，代码的可读性有多重要。其实并不需要每个地方都打上日志，这样我们在分析日志的时候也比较难快速定位关键信息。

我们要明白的一点是，「我们需要的不是日志，而是有效日志」。更何况，无效日志打多了，费磁盘~

只需要在我们关注的地方，打印关键的信息就可以了。比较常用的是我们通常能够快速定位数据的唯一id，比如gid等。

同步 vs 异步

我们知道，日志最终会输出到文件或者其它输出流，会重度使用IO。而异步可以显著提升IO性能，所以如果不是有特殊的需求，通常的建议使用异步的方式来输出日志。

以logback为例，要配置异步很简单，使用AsyncAppender就行：

<!--配置异步日志-->
<appender name="FILE_ASYNC" class="ch.qos.logback.classic.AsyncAppender">
    <appender-ref ref="ASYNC"/>
</appender>

trace Id

如今的系统做得越来越大，越来越复杂。前后端分离、分布式架构使得排查问题、追踪调用链路也变得越来越复杂。为了解决这个问题，我们可以使用一个trace Id来标识一次完整的调用链路。

目前主流的日志框架已经有这方面的支持了。拿logback为例，它提供了一种MDC机制，MDC为“Mapped Diagnostic Context”（映射诊断上下文），具体实现就是org.sl4j.MDC这个类。本文就不详细介绍如何使用它的了，感兴趣的同学可以去参考官方文档。

日志文件分离

我们打印日志是为了获取一些我们需要的信息。所以我们可以把不同类型的日志分离出去，比如access_log，或者ERROR级别的log，都可以单独打印到一个文件里。

也可以根据不同的业务模块，打印到不同的日志文件里，这样我们排查问题和做数据统计的时候就会比较方便。

获取日志实例

使用过日志框架的同学，对或多或少在类里定义过日志实例吧。但根据笔者的观察，大家定义日志的姿势各有千秋。有叫log的，有叫logger的，也有叫LOGGER的。定义的时候也都比较随意，比如不加static，不加final，获取实例的时候有传入this的，也有传入.class的。

这里不得不提一个优秀的Lombok注解：@Slf4j。它能够根据你的类自动注入一个log实例，非常方便快捷，如果你的项目使用了Lombok，不妨用起来。如果没有使用Lombok也没有关系，可以参考它的定义方式：

@Slf4j
public class Demo {

}

// 等价于：
public class Demo {
    private static final Logger log = LoggerFactory.getLogger(Demo.class);
}

以上，大家就可以愉快地打日志啦~

都看到这里了，说明你认可我的文章。
如果对你有帮助，不妨支持我一下：
你的一个小小的阅读、关注、留言、转发、在看，
都是我写作路上最大的鼓励。

猛戳下面那个二维码关注：