单元测试中日志性能首执行块额外开销问题咨询

问题描述 #

在结合单元测试测量日志性能时，发现首次执行的日志输出代码块会产生额外开销。以下是包含StringEscapeUtils.escapeJava的测试案例，其他测试中也出现该现象：

测试代码 #

import org.junit.jupiter.api.Test;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import java.time.Instant;
import java.util.Random;
import org.apache.commons.text.StringEscapeUtils;

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

    protected String getSaltString(final int length) {
        String SALTCHARS = "ABCDEFGHIJKLMNOPQRSTUVWXY\nZ1234567890";
        StringBuilder salt = new StringBuilder();
        Random rnd = new Random();
        while (salt.length() < length) { // length of the random string.
            int index = (int) (rnd.nextFloat() * SALTCHARS.length());
            salt.append(SALTCHARS.charAt(index));
        }
        String saltStr = salt.toString();
        return saltStr;

    }

    private void dummy(final String str) {

    }

    @Test
    public void testNewlineInString() {
        long start = 0, end = 0;
        final int Times = 1000;

        LOGGER.info("starting..");

        String [] strings = new String[Times];
        for (int i = 0; i < Times; ++i) {
            strings[i] = getSaltString(100);
        }

        LOGGER.info("Generated strings..");

        start = Instant.now().toEpochMilli();
        for (int i = 0; i < Times; ++i) {
            LOGGER.info("Case 1: String Number: {} Name: {}", i + 1, strings[i]);
//          dummy(strings[i]);
        }
        end = Instant.now().toEpochMilli();
        final long durationNo_escapeJava = end - start;

        start = Instant.now().toEpochMilli();
        for (int i = 0; i < Times; ++i) {
            LOGGER.info("Case 2: String Number: {} Name: {}", i + 1, StringEscapeUtils.escapeJava(strings[i]));
//          dummy(StringEscapeUtils.escapeJava(strings[i]));
        }
        end = Instant.now().toEpochMilli();
        final long duration_escapeJava = end - start;

        start = Instant.now().toEpochMilli();
        for (int i = 0; i < Times; ++i) {
            LOGGER.info("Case 3: String Number: {} Name: {}", i + 1, strings[i]);
//          dummy(strings[i]);
        }
        end = Instant.now().toEpochMilli();
        final long durationNo_escapeJavaAgain = end - start;


        LOGGER.info("durationNo_escapeJava: {} duration_escapeJava: {} durationNo_escapeJavaAgain: {}",
                durationNo_escapeJava, duration_escapeJava, durationNo_escapeJavaAgain);

    }
}

测试结果 #

测试结果持续显示，与第三块逻辑完全相同的第一块耗时远更长，例如：

durationNo_escapeJava: 265 duration_escapeJava: 107 durationNo_escapeJavaAgain: 28

尝试调用dummy函数时无此问题，询问该现象的原因。

原因分析 #

这种差异主要来自JVM运行时优化和日志框架的初始化开销，具体如下：

1. JVM即时编译（JIT）的预热延迟 #

JVM启动后，代码默认以解释模式执行，速度较慢。当某段代码（比如LOGGER.info的调用逻辑）被多次执行后，JVM的即时编译器会将其编译为本地机器码，大幅提升执行效率。

• Case 1是首次执行日志输出逻辑，此时JVM还未对这段热点代码进行编译，全程以解释模式运行，耗时较高；
• Case 3执行时，这段代码已经被JIT编译优化，所以耗时骤降；
• 而dummy方法是空实现，逻辑简单到没有触发JIT编译的必要，因此多次执行的耗时差异不明显。

2. 日志框架的初始化开销 #

首次调用LOGGER.info时，SLF4J及其绑定的日志实现（比如Logback、Log4j2）会完成一系列一次性初始化工作：

• 加载并初始化Logger上下文环境；
• 配置输出Appender（比如控制台输出的Appender）、日志格式器；
• 建立输出流连接、初始化占位符解析逻辑；
  这些操作只会在首次调用时执行，后续调用直接复用已初始化的资源，因此不会再产生额外开销。

3. 类加载与静态初始化开销 #

首次执行日志输出逻辑时，会触发大量相关依赖类（比如日志框架的内部工具类、字符串处理类）的加载和静态初始化，这些操作都需要额外的CPU和内存开销。后续调用时，这些类已经完成加载，无需重复执行。

内容的提问来源于stack exchange，提问作者user30360496