日志代码隐藏巨大性能陷阱


场景：我们有一个记录器，它应该只记录特定级别的消息（例如，info和warn）error，但不记录低于它的消息（debug或trace）。在运行时的某个时刻，我们应该能够提高或降低阈值。

一个简单的实现将获取级别并在运行时检查它，无论我们是否允许记录，然后仅在消息级别高于或等于配置的级别时才继续前进并记录。

// void trace(String message)

void debug(String message) {
    if (this.level.toInt() >= Level.DEBUG.toInt()) {
        // inner code to handle actual logging
    }
}

// void info(String message)
// void warn(String message)
// void error(String message)

这是自然代码，没有任何问题，但看起来是具有欺骗性的，并且该代码存在一些隐藏的细节，可能会使其性能不那么好。

在这个简单、看似无害的代码中存在两个隐藏的问题：

  1. 首先，在整个应用程序运行时，日志级别的更改频率远低于写入日志消息的频率，但我们却为所有日志调用付出了代价。事实上，您的应用程序可能永远不会在运行时更改日志级别。
  2. 然而，我们引入了运行时计算评估（代码中“>=”比较），它限制了我们的代码，并通过几乎不改变的谓词评估对其进行征税。

你可能会认为，由于你最终编写的代码，大部分日志调用都是信息、警告或错误，但实际上，引擎盖下的库添加了大量的调试和跟踪。这基本上意味着 CPU 缺乏可靠预测分支的模式，因此可能会因为无法预测代码执行路径而猝不及防，不得不放弃已经完成的工作。

因此，如果我们考虑这两个问题，我们希望通过尽快支付级别检查的成本来解决它们。此外，我们希望减少分支误预测成本。

如何解决？
上面描述的第一个问题与时间概念有很大关系，如果我们将时间想象成一条无限长的线，那么您的应用程序将在各种情况下正交地穿过它。

当我们设计应用程序或库时，当我们绘制某个层的图表时，当我们研究算法或数据结构来实现应用程序的某些功能时，时间轴中的所有这些事件都与我们的应用程序相关。此外，当我们编写代码、编译代码、部署代码以及运行代码时。所有这些事件都在时间的结构中编织着痕迹。

  • 与代码状态相关的分组称为some time
  • 那些在运行时发生的事件是 runtime
  • 应用程序和库还有其他“时间”，例如设计阶段时间、编译时间、打包时间和部署时间。

在 C 或 Rust 等语言中，我们可以使用宏和预处理器将许多决策移至编译时。在其他语言中，例如 clojure，宏在早期运行时被评估一次。

有些决策可以在运行时之前做出，但效果只会在运行时发生：
例如，java 中的一个常见情况是我们选择类路径中可用的库。分组、打包和部署 jar 不会导致任何更改，但是一旦应用程序启动，评估类路径并加载库，决策就会触发效果。

由于运行时发生很多事情，我认为可以公平地说，运行时存在“子时间”，例如应用程序初始化时间、配置时间、线程启动时间、jvm 预热时间等。其中一些可能重叠，并且之间可能存在一些模糊的线条。另外，不同的应用程序会有不同的子时间配置。然而，逻辑保持不变：在每个应用程序中，有些事情会在应用程序启动后发生，之后就不再发生，有些事情会不断发生，有些事情一旦发生就会触发其他事情发生，等等。

好吧，我为什么要告诉你这一切？

日志案例代码中：

  • 运行时期间“配置更改”时间发生的频率比“日志写入”时间发生的频率要低。
  • 此外，这样的推理可以解耦看似耦合的概念。例如，“日志写入”时间不需要支付与“配置更改”时间相关的成本，因为相对于其他时间，日志写入远远超过配置更改。

解耦这些概念可以让我们更清楚地看到这种优化机会。

还可以找到许多其他示例：写入日志会产生对象创建成本，写入 stdout 会产生 io 通道打开成本等。

识别这些事件、它们的发生率、它们之间的关系以及它们如何通过产生成本影响性能，是识别性能优化机会的强大工具。

有一篇关于过早优化的谬误的文章：
引用的完整版本是“我们应该忘记小的效率，大约 97% 的情况下：过早的优化是万恶之源。” 我同意这一点。在性能瓶颈显而易见之前，通常不值得花费大量时间对代码进行微优化。但是，相反，在系统级别设计软件时，应该从一开始就考虑性能问题。

解决方案
最近为使 java 现代且高效而做出的努力带来了诸如sealed types和 之类的功能default methods in interfaces，我们可以使用它们来实现优雅的解决方案。

让我们看一下这些日志方法，并思考如何在不付出“配置更改”时间成本的情况下重写它们。

抽象地说，这些方法充当我们的日志消息的门：

  1. 如果允许记录特定的日志级别，它会构建一个日志事件对象并将其传递通过门。
  2. 如果没有，那么它什么也不做。

我们可以从逻辑上将这些职责一分为二：

  1. 构建日志事件
  2. 并根据许可级别将其通过大门。

构建事件不可避免地是这里日志函数的责任，但我们可以将通过门的逻辑委托给其他东西，例如guard
这与我们之前的主题很好地产生了共鸣，因为每一项责任都可以在适当的时间发生，并且可以转移一些影响以最大程度地减少其影响。

在现实生活中，当你到达城堡的大门时，总会有一名守卫在那里。如果守卫只有在有人的时候才移动到大门，一旦访客离开，守卫就退回到城堡内部，这样效率就很低了。

这里解决方案遵循这一逻辑，日志事件的传递由 LevelGuard 决定，LevelGuard 是一个sealed interface密封接口，每个日志级别都有一个具体实现：

public sealed interface LevelGuard permits DebugLevelGuard, ErrorLevelGuard, InfoLevelGuard, TraceLevelGuard, WarnLevelGuard {

    default LogUnitContext get(PennaLogger logger, Level level) {
        // Internal logic
    }

    default boolean isTraceEnabled() {
        return false;
    }

    default LoggingEventBuilder trace(PennaLogger logger) {
        return NOPLoggingEventBuilder.singleton();
    }

    default boolean isDebugEnabled() {
        return false;
    }

    default LoggingEventBuilder debug(PennaLogger logger) {
        return NOPLoggingEventBuilder.singleton();
    }

    default boolean isInfoEnabled() {
        return true;
    }

    default LoggingEventBuilder info(PennaLogger logger) {
        return get(logger, Level.INFO);
    }

    default boolean isWarnEnabled() {
        return true;
    }

    default LoggingEventBuilder warn(PennaLogger logger) {
        return get(logger, Level.WARN);
    }

    default boolean isErrorEnabled() {
        return true;
    }

    default LoggingEventBuilder error(PennaLogger logger) {
        return get(logger, Level.ERROR);
    }
}

默认实现
LevelGuard
是有偏见的。
这是有意为之的。

事实上，如果你仔细观察，就会发现它与 INFO 级别的实现应该看起来差不多：INFO、WARN 和 ERROR 已启用，而 TRACE 和 DEBUG 则返回 NOPLoggingEventBuilder。

这样做是为了减少具有相同实现的重复 @Override 方法的数量，从而减少这些类的二进制大小。

这还可以简化这些类的实现，因为我们知道 DEBUG 防护只需额外允许调试级别，而 WARN 防护只需关闭信息方法，从而简化了这些防护的实现。

// DebugLevelGuard
public record DebugLevelGuard() implements LevelGuard {
    @Override
    public boolean isDebugEnabled() {
        return true;
    }

    @Override
    public LoggingEventBuilder debug(PennaLogger logger) {
        return get(logger, Level.DEBUG);
    }
}

// WarnLevelGuard
public record WarnLevelGuard() implements LevelGuard {
    @Override
    public boolean isInfoEnabled() {
        return false;
    }

    @Override
    public LoggingEventBuilder info(PennaLogger logger) {
        return NOPLoggingEventBuilder.singleton();
    }
}

另外，请注意巧妙的 NOPLoggingEventBuilder。它让我们的代码看起来一样，但不会产生副作用：

public final class PennaLogger implements IPennaLogger {

    // Simplified
    LevelGuard levelGuard;

    // constructor

    public void updateConfig(Config config) {
        //这就是支付 "配置更改 "费用的地方
        if (config.level() != levelGuard.level()) {
            // 我们将其委托给工厂，因为我们可以重复使用 guard 实例。
            // 因为它们是无状态的，所以可以在不同线程中共享同一个对象。
            levelGuard = getLevelGuardFromEnumValue(config.level());
        }
    }

    @Override
    public LoggingEventBuilder atTrace() {
        return levelGuard.trace(this);
    }

    @Override
    public void trace(String msg) {
        // 这种方法现在 "不受 "潜在配置更改的影响了
        atTrace().log(msg);
    }

    // all the other org.slf4j.Logger methods
}

由于我们的 LevelGuard 事先就知道所请求的级别是应该转发给 LoggingEventBuilder 的一个实现来实际构建事件并将其记录下来，还是应该直接扔给一个什么都不做的实现，因此无论如何，具体的 void trace(String msg) 实现看起来都是一样的。

现在，在我们继续之前，你可能会问我 "但是密封sealed 功能在这里有什么具体帮助"？从开发人员的角度来看，它可以让我们放心，所有必要的 Level 枚举值都会映射到 guard 中，不多也不少。从 JVM 的角度来看，我们为其提供了更多潜在运行时优化的信息。

这里的性能优化在于使用守护LevelGuard ，但使用上述功能可以让我们以更清晰、更容易推理的方式编写代码。我真希望你读到这里会想"嗯，这并不难"，因为认知负荷越高的变更就越容易出错。编写简单、优雅的代码肯定能带来出色的性能，因此这些功能的好处在于减轻了认知负荷。

一个重要的观察结果是：由于内联和其他 JVM 性能优化，更改 levelGuard 实例可能会对应用程序的即时性能产生一些影响，但与之前的方法不同的是，随着代码路径的热身和 JVM 对日志记录器类的重新编译，这种影响会随着时间的推移而摊销。

空谈误国，实干兴邦Talk is cheap, show me the benchmark
理论上听起来不错，但让我们看看一些数字，好吗？

下面的 JMH 基准显示了三种可能的情况：我们只有启用的日志级别，我们只有禁止的日志级别，或者我们有这两种级别的混合。请注意，在日志记录器层之后，将日志事件写成 json 的内部机制是相同的。在基准测试中，两种实现实际上都会在允许的情况下写入 json 消息，但它们将被 JMH 的黑洞（Blackhole）消耗，而不是 stdout，因此测试不会受到任何 IO 波动的影响。

public class LoggerPerformanceTest {

    @State(Scope.Thread)
    public static class TestState {
        @Param({
                "Penna",
                "IfBasedLogger"
        })
        PerfTestLoggerFactory.Implementation implementation;
        PerfTestLoggerFactory factory;
        Logger logger;

        @Setup
        public void setUp(Blackhole bh) {
            // Returns a concrete instance of our logger
            factory = PerfTestLoggerFactory.Factory.get(implementation);

            // Configures the logger to write to blackhole
            factory.setup(bh);

            // Gets a fancy logger
            logger = factory.getLogger("jmh." + implementation.name() + ".loggerTest");
        }

        @TearDown
        public void tearDown() throws IOException {
            factory.close();
        }

    }

    @Benchmark
    public void mixedLevels(TestState state) throws IOException {
        state.logger.atInfo().log("hello world");
        state.logger.atTrace().log("hello world");
        state.logger.atTrace().log("hello world");
        state.logger.atWarn().log("hello world");
        state.logger.atDebug().log("hello world");
        state.logger.atError().log("hello world");
    }

    @Benchmark
    public void onlyAllowed(TestState state) throws IOException {
        state.logger.atInfo().log("hello world");
        state.logger.atWarn().log("hello world");
        state.logger.atError().log("hello world");
    }

    @Benchmark
    public void onlyForbidden(TestState state) throws IOException {
        state.logger.atTrace().log("hello world");
        state.logger.atTrace().log("hello world");
        state.logger.atDebug().log("hello world");
    }

    // public static void main(String args) omitted for simplicity
}

输出：
/*
Benchmark                            (implementation)   Mode  Cnt     Score    Error   Units
LoggerPerformanceTest.mixedLevels               Penna  thrpt    6     1.900 ±  0.109  ops/us
LoggerPerformanceTest.mixedLevels       IfBasedLogger  thrpt    6     1.005 ±  0.065  ops/us
LoggerPerformanceTest.onlyAllowed               Penna  thrpt    6     1.961 ±  0.198  ops/us
LoggerPerformanceTest.onlyAllowed       IfBasedLogger  thrpt    6     1.915 ±  0.115  ops/us
LoggerPerformanceTest.onlyForbidden             Penna  thrpt    6  1148.778 ± 76.608  ops/us
LoggerPerformanceTest.onlyForbidden     IfBasedLogger  thrpt    6     2.027 ±  0.127  ops/us
*/

这些数字很有意思，我们可以从中学习到很多东西。

例如，如果我们只看基于 IfBasedLogger 的数据，我们会注意到，无论是允许记录所有消息还是不允许记录任何消息，它的性能都是一致的。

此外，通过使用 LevelGuard 方法，我们在只允许记录和混合记录两种级别之间保持了一致，因为不会出现分支遗漏。

从结果中观察到的最后一个有趣现象是，什么都不做比进行检查要有效得多。使用 NOPLoggingEventBuilder 会比基于检查的版本快三个数量级。

总结
现代 Java 是您的好朋友，它允许使用密封类型和默认方法实现等良好特性，从而提供简洁、干净和高性能的解决方案。事实上，无分支代码并不需要使用巧妙的位运算来躲避 if 块。它可以被提升到代码架构中，通过有意识的深思熟虑的设计来处理。

虽然本文没有讨论，但我们选择使用密封接口而不是通常的接口，这对性能肯定会产生（微小的）积极影响，但如果要深入探讨这些令人讨厌的细节，本文的篇幅将大大增加。

（banq注：实际使用了缓存了工厂模式创建的实例结果，引入有状态，降低了if判断的成本，有助于JVM优化）