日志记录的坑

阿璐4r

已于 2022-02-12 14:45:45 修改

阅读量618

点赞数

分类专栏：学习笔记文章标签：学习笔记

于 2022-01-20 10:28:32 首次发布

本文链接：https://blog.csdn.net/asc_123456/article/details/122595988

版权

学习笔记专栏收录该内容

11 篇文章 1 订阅

订阅专栏

日志框架众多，不同的类库可能会使用不同的日志框架，如何兼容是一个问题。
配置复杂且容易出错。日志配置文件通常很复杂，因此有些开发同学会从其他项目或者网络上复制一份配置文件，但却不知道如何修改，甚至是胡乱修改，造成很多问题。比如，重复记录日志的问题、同步日志的性能问题、异步记录的错误配置问题。
日志记录本身就有些误区，比如没考虑到日志内容获取的代价、胡乱使用日志级别等。

1.SLF4J

提供了统一的日志门面 API，即图中紫色部分，实现了中立的日志记录 API。
用来把各种日志框架的 API 桥接到 SLF4J API。这样一来，即便你的程序中使用了各种日志 API 记录日志，最终都可以桥接到 SLF4J 门面 API。
可以实现 SLF4J API 和实际日志框架的绑定。SLF4J 只是日志标准，我们还是需要一个实际的日志框架。日志框架本身没有实现 SLF4J API，所以需要有一个前置转换。Logback 就是按照 SLF4J API 标准实现的，因此不需要绑定模块做转换。

业务系统使用最广泛的是 Logback 和 Log4j，它们是同一人开发的。Logback 可以认为是 Log4j 的改进版本，Spring Boot 是目前最流行的 Java 框架，它的日志框架也用的是 Logback。

2.日志重复记录

logger 配置继承关系导致日志重复记录

@Log4j2
@RequestMapping("logging")
@RestController
public class LoggingController {
    @GetMapping("log")
    public void log() {
        log.debug("debug");
        log.info("info");
        log.warn("warn");
        log.error("error");
    }
}

使用下面的 Logback 配置

<?xml version="1.0" encoding="UTF-8" ?>
<configuration>
    <appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
        <layout class="ch.qos.logback.classic.PatternLayout">
            <pattern>[%d{yyyy-MM-dd HH:mm:ss.SSS}] [%thread] [%-5level] [%logger{40}:%line] - %msg%n</pattern>
        </layout>
    </appender>
    <logger name="org.geekbang.time.commonmistakes.logging" level="DEBUG">
        <appender-ref ref="CONSOLE"/>
    </logger>
    <root level="INFO">
        <appender-ref ref="CONSOLE"/>
    </root>
</configuration>

执行方法后出现了日志重复记录的问题：
从配置文件的第 9 和 12 行可以看到，CONSOLE 这个 Appender 同时挂载到了两个 Logger 上，一个是我们定义的，一个是，由于我们定义的继承自，所以同一条日志既会通过 logger 记录，也会发送到 root 记录，因此应用 package 下的日志出现了重复记录。
修改：

<?xml version="1.0" encoding="UTF-8" ?>
<configuration>
    <appender name="FILE" class="ch.qos.logback.core.FileAppender">
        <file>app.log</file>
        <encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
            <pattern>[%d{yyyy-MM-dd HH:mm:ss.SSS}] [%thread] [%-5level] [%logger{40}:%line] - %msg%n</pattern>
        </encoder>
    </appender>
    <appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
      <layout class="ch.qos.logback.classic.PatternLayout">
            <pattern>[%d{yyyy-MM-dd HH:mm:ss.SSS}] [%thread] [%-5level] [%logger{40}:%line] - %msg%n</pattern>
      </layout>
   </appender>
    <logger name="org.geekbang.time.commonmistakes.logging" level="DEBUG" additivity="false">
        <appender-ref ref="FILE"/>
    </logger>
   <root level="INFO">
      <appender-ref ref="CONSOLE" />
   </root>
</configuration>

错误配置 LevelFilter 造成日志重复记录
把日志记录按照不同的级别记录到两个文件中：

<?xml version="1.0" encoding="UTF-8" ?>
<configuration>
   <property name="logDir" value="./logs" />
   <property name="app.name" value="common-mistakes" />
   <appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
      <layout class="ch.qos.logback.classic.PatternLayout">
         <pattern>[%d{yyyy-MM-dd HH:mm:ss.SSS}] [%thread] [%-5level] [%logger{40}:%line] - %msg%n</pattern>
      </layout>
   </appender>
   <appender name="INFO_FILE" class="ch.qos.logback.core.FileAppender">
      <File>${logDir}/${app.name}_info.log</File>
      <filter class="ch.qos.logback.classic.filter.LevelFilter">
         <level>INFO</level>
      </filter>
      <encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
         <pattern>[%d{yyyy-MM-dd HH:mm:ss.SSS}] [%thread] [%-5level] [%logger{40}:%line] - %msg%n</pattern>
         <charset>UTF-8</charset>
      </encoder>
   </appender>
   <appender name="ERROR_FILE" class="ch.qos.logback.core.FileAppender
">
      <File>${logDir}/${app.name}_error.log</File>
      <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
         <level>WARN</level>
      </filter>
      <encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
         <pattern>[%d{yyyy-MM-dd HH:mm:ss.SSS}] [%thread] [%-5level] [%logger{40}:%line] - %msg%n</pattern>
         <charset>UTF-8</charset>
      </encoder>
   </appender>
   <root level="INFO">
      <appender-ref ref="CONSOLE" />
      <appender-ref ref="INFO_FILE"/>
      <appender-ref ref="ERROR_FILE"/>
   </root>
</configuration>

第 31 到 35 行定义的 root 引用了三个 Appender。第 5 到 9 行是第一个 ConsoleAppender，用于把所有日志输出到控制台。第 10 到 19 行定义了一个 FileAppender，用于记录文件日志，并定义了文件名、记录日志的格式和编码等信息。最关键的是，第 12 到 14 行定义的 LevelFilter 过滤日志，将过滤级别设置为 INFO，目的是希望 _info.log 文件中可以记录 INFO 级别的日志。第 20 到 30 行定义了一个类似的 FileAppender，并使用 ThresholdFilter 来过滤日志，过滤级别设置为 WARN，目的是把 WARN 以上级别的日志记录到另一个 _error.log 文件中。运行程序_info.log 中包含了 INFO、WARN 和 ERROR 三个级别的日志，不符合我们的预期，由于没有配置 onMatch 和 onMismatch 属性，所以相当于这个过滤器是无用的，导致 INFO 以上级别的日志都记录了。
修复：

<appender name="INFO_FILE" class="ch.qos.logback.core.FileAppender">
  <File>${logDir}/${app.name}_info.log</File>
  <filter class="ch.qos.logback.classic.filter.LevelFilter">
    <level>INFO</level>
    <onMatch>ACCEPT</onMatch>
    <onMismatch>DENY</onMismatch>
  </filter>
  ...
</appender>

3.使用异步日志改善性能

如何避免日志记录成为应用的性能瓶颈。这可以帮助我们解决，磁盘（比如机械磁盘）IO 性能较差、日志量又很大的情况下，如何记录日志的问题

<?xml version="1.0" encoding="UTF-8" ?>
<configuration>
    <appender name="FILE" class="ch.qos.logback.core.FileAppender">
        <file>app.log</file>
        <encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
            <pattern>[%d{yyyy-MM-dd HH:mm:ss.SSS}] [%thread] [%-5level] [%logger{40}:%line] - %msg%n</pattern>
        </encoder>
    </appender>
    <appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
        <layout class="ch.qos.logback.classic.PatternLayout">
            <pattern>[%d{yyyy-MM-dd HH:mm:ss.SSS}] [%thread] [%-5level] [%logger{40}:%line] - %msg%n</pattern>
        </layout>
        <filter class="ch.qos.logback.core.filter.EvaluatorFilter">
            <evaluator class="ch.qos.logback.classic.boolex.OnMarkerEvaluator">
                <marker>time</marker>
            </evaluator>
            <onMismatch>DENY</onMismatch>
            <onMatch>ACCEPT</onMatch>
        </filter>
    </appender>
    <root level="INFO">
        <appender-ref ref="FILE"/>
        <appender-ref ref="CONSOLE"/>
    </root>
</configuration>

测试代码中，实现了记录指定次数的大日志，每条日志包含 1MB 字节的模拟数据，最后记录一条以 time 为标记的方法执行耗时日志

@GetMapping("performance")
public void performance(@RequestParam(name = "count", defaultValue = "1000") int count) {
    long begin = System.currentTimeMillis();
    String payload = IntStream.rangeClosed(1, 1000000)
            .mapToObj(__ -> "a")
            .collect(Collectors.joining("")) + UUID.randomUUID().toString();
    IntStream.rangeClosed(1, count).forEach(i -> log.info("{} {}", i, payload));
    Marker timeMarker = MarkerFactory.getMarker("time");
    log.info(timeMarker, "took {} ms", System.currentTimeMillis() - begin);
}

执行程序后可以看到，记录 1000 次日志和 10000 次日志的调用耗时，分别是 6.3 秒和 44.5 秒，源码中在追加日志的时候，是直接把日志写入 OutputStream 中，属于同步记录日志
使用 Logback 提供的 AsyncAppender 即可实现异步的日志记录。AsyncAppende 类似装饰模式，也就是在不改变类原有基本功能的情况下为其增添新功能。这样，我们就可以把 AsyncAppender 附加在其他的 Appender 上，将其变为异步的。测试一下可以发现，记录 1000 次日志和 10000 次日志的调用耗时，分别是 735 毫秒和 668 毫秒：

<appender name="ASYNCFILE" class="ch.qos.logback.classic.AsyncAppender">
    <appender-ref ref="FILE"/>
</appender>
<root level="INFO">
    <appender-ref ref="ASYNCFILE"/>
    <appender-ref ref="CONSOLE"/>
</root>

但是使用异步日志也存在问题：

记录异步日志撑爆内存；
记录异步日志出现日志丢失；
记录异步日志出现阻塞。
AsyncAppender提供了一些默认参数
includeCallerData 用于控制是否收集调用方数据，默认是 false，此时方法行号、方法名等信息将不能显示
queueSize 用于控制阻塞队列大小，使用的 ArrayBlockingQueue 阻塞队列，默认大小是 256，即内存中最多保存 256 条日志。
discardingThreshold 是控制丢弃日志的阈值，主要是防止队列满后阻塞。
neverBlock 用于控制队列满的时候，加入的数据是否直接丢弃，不会阻塞等待，默认是 false

默认队列大小为 256，达到 80% 容量后开始丢弃 <=INFO 级别的日志，但queueSize 设置得特别大，就可能会导致 OOM。neverBlock 默认为 false，意味着总可能会出现阻塞

4.日志占位符就不需要进行日志级别判断了？

private String slowString(String s) {
    System.out.println("slowString called via " + s);
    try {
        TimeUnit.SECONDS.sleep(1);
    } catch (InterruptedException e) {
    }
    return "OK";
}


StopWatch stopWatch = new StopWatch();
stopWatch.start("debug1");
log.debug("debug1:" + slowString("debug1"));
stopWatch.stop();
stopWatch.start("debug2");
log.debug("debug2:{}", slowString("debug2"));
stopWatch.stop();
stopWatch.start("debug3");
if (log.isDebugEnabled())
    log.debug("debug3:{}", slowString("debug3"));
stopWatch.stop();

前两种方式都调用了 slowString 方法，所以耗时都是 1 秒
修改：

@Log4j2
public class LoggingController {
...
log.debug("debug4:{}", ()->slowString("debug4"));

阿璐4r

关注

0
点赞
踩
0

收藏

觉得还不错? 一键收藏
0
评论
日志记录的坑

日志框架众多，不同的类库可能会使用不同的日志框架，如何兼容是一个问题。配置复杂且容易出错。日志配置文件通常很复杂，因此有些开发同学会从其他项目或者网络上复制一份配置文件，但却不知道如何修改，甚至是胡乱修改，造成很多问题。比如，重复记录日志的问题、同步日志的性能问题、异步记录的错误配置问题。日志记录本身就有些误区，比如没考虑到日志内容获取的代价、胡乱使用日志级别等。1.SLF4J提供了统一的日志门面 API，即图中紫色部分，实现了中立的日志记录 API。用来把各种日志框架的 API 桥接到 S.
复制链接

扫一扫

专栏目录