java - 使用 slf4j API 的 logback 的性能问题

Question

我正在使用 Windows 机器来获取 logback + slf4j 的性能结果

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import ch.qos.logback.classic.Level;

public class LogPerformanceAnalyser {
    private static final Logger LOG =
            LoggerFactory.getLogger(LogPerformanceAnalyser.class);

    public LogPerformanceAnalyser() {
        ((ch.qos.logback.classic.Logger) LOG).setLevel(Level.ERROR);
    }

    public long getTimeWithCheck() {
        long startTime = System.currentTimeMillis();
        for (int i = 0; i < Integer.MAX_VALUE; i++) {
            if (LOG.isDebugEnabled()) {
                LOG.debug("This log is {} check", "with");
            }
        }
        return System.currentTimeMillis() - startTime;
    }

    public long getTimeWithoutCheck() {
        long startTime = System.currentTimeMillis();
        for (int i = 0; i < Integer.MAX_VALUE; i++) {
            LOG.debug("This log is {} check", "without");
        }
        return System.currentTimeMillis() - startTime;
    }
}

注意-1.调试关闭2. 运行 10 次得到平均结果。

性能结果是:

Total Time getTimeWithoutCheck: 26900 ms
Total Time getTimeWithCheck : 22536 ms

结果是在记录之前放置检查为 217 亿条日志节省了约 3.5 秒。

如果我将 Logger 更改为非静态:

private final Logger LOG = 
        LoggerFactory.getLogger(LogPerformanceAnalyser.class);

我得到以下信息:

Total Time getTimeWithoutCheck: 37095 ms
Total Time getTimeWithCheck : 47006 ms

谁能解释一下？

Answer 1

首先，您需要正确的基准。在 Java 世界中，JMH 是事实上的基准测试标准。

基准:

@BenchmarkMode(Mode.AverageTime)
@OutputTimeUnit(TimeUnit.NANOSECONDS)
@State(Scope.Thread)
public class LogBench {
    private static final Logger LOG = LoggerFactory.getLogger(LogBench.class);

    private final Logger localLog = LoggerFactory.getLogger(LogBench.class);


    @Benchmark
    public long baseline() {
        return 0;
    }

    @Benchmark
    public void getTimeWithCheck() {
        if (LOG.isTraceEnabled()) {
            LOG.trace("This log is {} check", "with");
        }
    }

    @Benchmark
    public void getTimeWithoutCheck() {
        LOG.trace("This log is {} check", "without");
    }

    @Benchmark
    public void getTimeWithCheckBenchLocal() {
        if (localLog.isTraceEnabled()) {
            localLog.trace("This log is {} check", "with");
        }
    }

    @Benchmark
    public void getTimeWithoutCheckLocal() {
        localLog.trace("This log is {} check", "without");
    }
}

我将调试更改为跟踪以避免强制转换的可能影响。

结果

    Benchmark                                     Mode   Samples        Score  Score error    Units
    o.o.j.s.LogBench.baseline                     avgt         3        0.539        0.047    ns/op
    o.o.j.s.LogBench.getTimeWithCheck             avgt         3        1.030        0.083    ns/op
    o.o.j.s.LogBench.getTimeWithCheckLocal        avgt         3        1.637        0.571    ns/op
    o.o.j.s.LogBench.getTimeWithoutCheck          avgt         3        1.140        0.112    ns/op
    o.o.j.s.LogBench.getTimeWithoutCheckLocal     avgt         3        1.628        0.311    ns/op

你可以看到，条件检查在这里没有用，但是静态版本比本地快 1.6 倍。让我们开始探索 getTimeWithCheckLocal 和 getTimeWithCheck 之间的区别。

静态日志程序集

Beginning of getTimeWithCheck:
[Verified Entry Point]
  0x00007f06b920b440: mov    DWORD PTR [rsp-0x14000],eax
  0x00007f06b920b447: push   rbp
  0x00007f06b920b448: sub    rsp,0x20           ;*synchronization entry
                                            ; - org.openjdk.jmh.samples.LogBench::getTimeWithoutCheck@-1 (line 65)

execution:
  0x00007f06b920b44c: movabs r10,0x76d8bdfd0    ;   {oop(a 'ch/qos/logback/classic/Logger')}
  0x00007f06b920b456: mov    r11d,DWORD PTR [r10+0x28] ;*getfield loggerContext
  0x00007f06b920b45a: mov    r9d,DWORD PTR [r12+r11*8+0x60]  ;*getfield turboFilterList
  0x00007f06b920b45f: mov    r8d,DWORD PTR [r12+r9*8+0x10] ;*getfield array
...     

非静态 LOG 程序集

[Verified Entry Point]
  0x00007f1c592111e0: mov    DWORD PTR [rsp-0x14000],eax
  0x00007f1c592111e7: push   rbp
  0x00007f1c592111e8: sub    rsp,0x30           ;*synchronization entry
                                            ; - org.openjdk.jmh.samples.LogBench::getTimeWithoutCheckLocal@-1 (line 77)

  0x00007f1c592111ec: mov    r11d,DWORD PTR [rsi+0xc]  ;*getfield localLog
  0x00007f1c592111f0: mov    r10d,DWORD PTR [r12+r11*8+0x8] ; implicit exception: dispatches to 0x00007f1c59211281
  0x00007f1c592111f5: cmp    r10d,0xf80154ad    ;   {metadata('ch/qos/logback/classic/Logger')}
  0x00007f1c592111fc: jne    0x00007f1c5921123c

execution:
  0x00007f1c592111fe: lea    r8,[r12+r11*8]     ;*invokeinterface debug
  0x00007f1c59211202: mov    ecx,DWORD PTR [r8+0x28]  ;*getfield loggerContext                                                                                     

您会注意到，在第二个实验中，JIT 必须对 Logger 字段值执行额外的加载:lea r9,[r12+r10*8]。

让我们使用 perfasm 分析器再次运行基准测试

0.04%    0.04%  │↗  0x00007f6c25229320: mov    r10d,DWORD PTR [r8+0xc]  ;*getfield localLog
                ││                                                ; - org.openjdk.jmh.samples.LogBench::getTimeWithoutCheckLocal@1 (line 77)
                ││                                                ; - org.openjdk.jmh.samples.generated.LogBench_getTimeWithoutCheckLocal_jmhTest::getTimeWithoutCheckLocal_avgt_jmhStub@14 (line 163)
6.80%    7.29%  ││  0x00007f6c25229324: mov    r11d,DWORD PTR [r12+r10*8+0x8]
                ││                                                ; implicit exception: dispatches to 0x00007f6c252294a5
         0.02%  ││  0x00007f6c25229329: cmp    r11d,0xf80197b1    ;   {metadata('ch/qos/logback/classic/Logger')}
                ││  0x00007f6c25229330: jne    0x00007f6c2522939b
                ││  0x00007f6c25229332: lea    r9,[r12+r10*8]     ;*invokeinterface debug
                ││  0x00007f6c25229336: mov    ecx,DWORD PTR [r9+0x28]  ;*getfield loggerContext

如您所见，这种额外加载并不是免费的。这是因为存在很多更改 final 变量的方法，因此对字段执行此优化是不安全的。

由于jvm的实验特性有一个特殊的选项-XX:+TrustFinalNonStaticFields，它必须与-XX:+UnlockExperimentalVMOptions一起使用。如果您使用此选项运行基准测试，您将看到另一个结果:

Benchmark                            Mode  Cnt  Score   Error  Units
LogBench.baseline                    avgt    3  2.124 ± 0.907  ns/op
LogBench.getTimeWithCheck            avgt    3  0.695 ± 0.231  ns/op
LogBench.getTimeWithCheckBenchLocal  avgt    3  1.608 ± 0.140  ns/op
LogBench.getTimeWithoutCheck         avgt    3  0.675 ± 0.075  ns/op
LogBench.getTimeWithoutCheckLocal    avgt    3  1.613 ± 0.176  ns/op

结果很奇怪，尽管现在没有额外加载局部变量，内联被破坏，asm 代码包含直接调用:

0x00007f2355205d33: call   0x00007f2355046020  ; OopMap{off=120}
                                            ;*invokespecial filterAndLog_1

结论

• JVM 不信任 final 字段，因此每次在基准测试中它都必须从内存中加载它(但在 99.999999% 的应用程序中这不会成为问题)
• JVM 有 experimental option TrustFinalNonStaticFields 这似乎很不稳定，因为它破坏了 CHA 优化