为什么要求开发者对Logger再封装

2023/11/29 | 60 | 0 | Spring

摘要

在《嵩山版阿里Java开发手册》的日志规约中第一条明确规定了：应用中不可直接使用日志系统（Log4j、Logback）中的 API，而应依赖使用日志框架（SLF4J、JCL--Jakarta Commons Logging）中的 API，使用门面模式的日志框架开发。
Apache曾道：“在没有错误日志的情况下对任何问题进行故障排除无异于闭眼开车”，可见日志的重要性。在日常开发过程中，打印日志是必不可少的操作步骤，因为日志关乎于应用的问题排查、应用监控等。现如今的应用开发中日志打印一般都是SLF4J来实现的，使用日志门面模式，不仅有助于打印方式统一，也使得后面更换日志框架更加方便。

日志规约

常规使用

以SLF4J为例，在日常开发中开发者会通过如下的两种方法来使用日志打印：

private static final Logger LOGGER = LoggerFactory.getLogger(LoggerTest.class);
@Test
public void LoggerTestUnit() {
	log.info("successfully loaded {} beans", 3); // @SLF4J注解式
	LOGGER.info("successfully loaded {} beans", beanContainer.size()); // Logger工厂
}

但是很多时候再企业的框架开发中会对这种Logger方法再进行一次封装，最终的形式可能如下：

LoggerUtil.info(LOGGER, "print: {}", "this is the log");

问题产生

很多人觉得SLF4J本来就是日志门面，已经封装的很好了，为什么要多此一举，再额外封装一个 LoggerUtil 来输出日志呢？其实这块也是在开发规范中也有相应的说明：

为什么要封装

这段话简单翻译过来的意思是：无论是否启用一个日志级别，该方法都会先将参数进行处理（这个是Java本身导致的），再进入Logger中判断有没有启用这个日志级别来决定是否输出。
当这些参数中包含了如JSON.toJSONString(error)等一些复杂的处理方法时，这些方法会最先被执行再传递给Logger来输出，以下是一个模拟的案例：

@Test
public void LoggerTestUnit() {
    long startTime = System.currentTimeMillis();
    LOGGER.info("info {}", mockComplexMsgProcess(new Object()));
    System.out.println("this execution spends " + (System.currentTimeMillis() - startTime) + " ms");
}

public String mockComplexMsgProcess(Object infomation) {
    if (infomation == null) {
        throw new NullPointerException("information can't be null");
    }
    // 这里模拟一个极为复杂的info中对象的处理方法，这个过程需要耗时3s
    try {
        Thread.sleep(3000);
    } catch (InterruptedException e) {
        throw new RuntimeException(e);
    }
    return infomation.toString();
}

在测试结果中这个方法耗时3002ms，虽然只是输出日志信息但是整个方法在mockComplexMsgProcess阶段耗费了大量的时间。这种打印日志会对很多大促、秒杀等高并发场景造成很大的影响，当服务接收到海量请求时，又会产生大量的日志IO操作对服务器的性能也会造成不可估量的影响。

尝试解决问题

完全关闭日志可能并不是一个很好的方案，因为日志可以提供系统运行情况的重要信息，对于诊断问题，尤其是在大促等重要时刻，这些信息可能会非常关键。因此，一些可行的解决方案是调整日志策略，如：

调整日志级别：你可以把日志级别调整为错误或警告，只记录关键的信息。
异步日志：你可以使用异步的方式写入日志，这样可以减少日志写入对主程序的影响。
日志采样：对于某些类型的日志，你可以选择采样一部分，而不是记录全部。
使用专门的日志服务：例如，使用Fluentd或Logstash这样的日志收集工具，把日志发送到ElasticSearch、CloudWatch Logs等服务中进行分析。
高效的日志格式：使用结构化的日志格式（如JSON）可以方便后续的处理和分析，同时也可以减小日志的体积。
使用分布式追踪系统：在微服务架构中，使用分布式追踪系统（如Jaeger、Zipkin）可以帮助你在海量的请求中追踪特定的请求，定位问题。
磁盘I/O和网络I/O：如果你的日志系统支持，可以考虑把日志写入到一个低优先级的I/O队列，或者使用一个单独的网络连接发送日志，以减少对主程序的影响。

这里重点以第一种方法为切入点，以slf4j-simple为例可以在需要高并发的环境中将日志级别提高为error（System.setProperty("org.slf4j.simpleLogger.defaultLogLevel", "error");）这样只会选择性地输出重要的error类型的日志：

private static final Logger LOGGER = LoggerFactory.getLogger(LoggerTest.class);

@Test
public void loggerTest() {
	// 提高日志等级
    System.setProperty("org.slf4j.simpleLogger.defaultLogLevel", "error");
    long startTime = System.currentTimeMillis();
    LOGGER.debug("{}", mockSlowArgument("Dioxide_CN", "testing"));
    System.out.println("this logger cost " + (System.currentTimeMillis() - startTime) + " ms");
}

public String mockSlowArgument(String name, String info) {
    try {
        Thread.sleep(3000);
    } catch (InterruptedException e) {
        throw new RuntimeException(e);
    }
    return name + "-" + info;
}

如果读者仔细分析上面这段代码还是很容易地发现这也不能解决延迟的问题，只是单纯的减少了日志IO的开销。但是可以加上以下的日志级别判断来预处理这些日志是否需要被调用：

if (LOGGER.isDebugEnabled()) {
	LOGGER.debug("{}", mockSlowArgument("Dioxide_CN", "testing"));
}

为了避免每次都要if判断的问题，开发者通常会将if模块封装为工具类，这就是在文章开头提到的LogUtils工具。但是这种情况只能避免打印“既有参数”时的 if 判断，对“方法类型”的参数没有作用。因而这也不能作为开发中的最终LogUtils进行调用，作为开发者我们应该考虑一种能让参数懒加载（延迟加载）的方法。

函数式接口与延迟链

Supplier作为一种可以获取结果的函数式接口是用作延迟加载方法的不二之选。我们完全可以将前文中的mockSlowArgument方法委派给Supplier接口，并加入判断日志等级是否启用，来实现更加精准的延迟加载日志工具封装。这里给出一个简单的示例：

public class LoggerTest {

    @Test
    public void lazyLoggerTest() {
        System.setProperty("org.slf4j.simpleLogger.defaultLogLevel", "error");
        long startTime = System.currentTimeMillis();
        // 这语句会被日志等级判断阻拦
        LogUtils.info(LoggerTest.class, "Hello! {} this is INFO", () -> mockSlowArgument("Dioxide", "CN"));
        // 这个语句会被调用
        LogUtils.error(LoggerTest.class, "Hello! {} this is ERROR", () -> mockSlowArgument("Dioxide", "CN"));
        System.out.println("this logger cost " + (System.currentTimeMillis() - startTime) + " ms");
    }

    public String mockSlowArgument(String name, String info) {
        try {
            Thread.sleep(3000);
        } catch (InterruptedException e) {
            throw new RuntimeException(e);
        }
        return name + "-" + info;
    }

}

/**
 * 封装LogUtils实现延迟加载与日志等级判断
 * @author Dioxide.CN
 * @date 2023/5/24
 */
class LogUtils {

    private LogUtils() {}

    public static void info(Class<?> clazz, String message, Supplier<?>... suppliers) {
        log(Level.INFO, clazz, message, suppliers);
    }

    public static void debug(Class<?> clazz, String message, Supplier<?>... suppliers) {
        log(Level.DEBUG, clazz, message, suppliers);
    }

    public static void warn(Class<?> clazz, String message, Supplier<?>... suppliers) {
        log(Level.WARN, clazz, message, suppliers);
    }

    public static void error(Class<?> clazz, String message, Supplier<?>... suppliers) {
        log(Level.ERROR, clazz, message, suppliers);
    }

    public static void trace(Class<?> clazz, String message, Supplier<?>... suppliers) {
        log(Level.TRACE, clazz, message, suppliers);
    }
    private static void log(Level level, Class<?> clazz, String message, Supplier<?>... suppliers) {
        Logger logger = LoggerFactory.getLogger(clazz);
        // 判断日志级别是否被启用
        switch (level) {
            case DEBUG -> {
                if (logger.isDebugEnabled()) {
                    logger.debug(message, getLogArgs(suppliers));
                }
            }
            case INFO -> {
                if (logger.isInfoEnabled()) {
                    logger.info(message, getLogArgs(suppliers));
                }
            }
            case ERROR -> {
                if (logger.isErrorEnabled()) {
                    logger.error(message, getLogArgs(suppliers));
                }
            }
            case WARN -> {
                if (logger.isWarnEnabled()) {
                    logger.warn(message, getLogArgs(suppliers));
                }
            }
            case TRACE -> {
                if (logger.isTraceEnabled()) {
                    logger.trace(message, getLogArgs(suppliers));
                }
            }
            default ->
                    throw new IllegalArgumentException("Unexpected Level: " + level);
        }
    }

    private static Object[] getLogArgs(Supplier<?>... suppliers) {
        if (suppliers == null || suppliers.length == 0) {
            return new Object[]{};
        } else {
            return Arrays.stream(suppliers).map(Supplier::get).toArray();
        }
    }

}

经过一系列的封装，一个简易的LogUtils就成功被实现了，因为启用了error级别的日志输出等级所以这里只有error等级的日志会被输出，不出所料的是这个方法执行的时间只会在3000+100毫秒左右而不是6000+100毫秒。
封装LogUtils

SLF4J 2.0

上述的实现原理与封装在 log4j-api-2.17.2 的util.Logger接口中也有所体现，只不过slf4j日志门面里面并没有封装 Supplier 支持，详细实现读者可以自行阅读源码。
那为什么 slf4j 不支持，其实也是有讨论的，可以看Add jdk 1.8 suppport by ouertani · Pull Request #70 · qos-ch/slf4j (github.com)这个issue，里面进行了一系列讨论，大致的内容就不再赘述。最终结果是在slf4j-2.0中支持了Fluent Logging API语法，其使用方法如下：

@Test
public void loggerTest() {
    System.setProperty("org.slf4j.simpleLogger.defaultLogLevel", "error");
    Logger LOGGER = LoggerFactory.getLogger(LoggerTest.class);
    
    long startTime = System.currentTimeMillis();
    LOGGER
            .atInfo()
            .setMessage("{}")
            .addArgument(() -> mockSlowArgument("Dioxide_CN", "testing"))
            .log();
    LOGGER
            .atError()
            .setMessage("{}")
            .addArgument(() -> mockSlowArgument("Dioxide_CN", "testing"))
            .log();
    System.out.println("this logger cost " + (System.currentTimeMillis() - startTime) + " ms");
}

最终的结果也是在3000+100毫秒左右波动并且只输出error部分的日志。需要注意的是，SLF4J的Fluent API依赖于Logger的具体实现（例如Logback或Log4j）。具体的日志记录操作，例如消息的格式化，参数的替换等，仍然是由Logger的实现来完成的。
在调整日志策略或封装日志工具时，开发者仍然需要平衡“性能”和“可观察性”的需求，这可能需要在实际环境中进行一些测试和调整。

参考文献

[1] 刘志航. (2022, September 26). 打印 Logger 日志时，需不需要再封装一下工具类？. https://liuzhihang.com/archives/logger-util
[2] SLF4J. (n.d.). SLF4J Manual - Fluent Logging API. https://www.slf4j.org/manual.html#fluent
[3] QOS.CH. (n.d.). SLF4J. https://github.com/qos-ch/slf4j
[4] 阿里巴巴. (2020, August 3). 嵩山版阿里Java开发规约.

目录大纲