本来打算写一篇《阿里巴巴为什么不允许日志输出时，使用字符串拼接？》的文章，主要是想从性能方面来说此问题，可在文章写到一半进行性能测试时，却发现了一个异常问题，实际测试的结果和手册上描述的结果是截然相反的！
天撸了，怎么会发生这种事情？此时我的内心是拒绝的，因为文章已经写了一半了啊，这让我瞬间陷入了尴尬的境地。
阿里巴巴的《Java开发手册》泰山版（最新版）是这样描述的，它在第二章第三小节的第 4 条规范中指出：
【强制】在日志输出时，字符串变量之间的拼接使用占位符的方式。
说明：因为 String 字符串的拼接会使用 StringBuilder 的 append() 方式，有一定的性能损耗。使用占位符仅 是替换动作，可以有效提升性能。
正例：logger.debug("Processing trade with id: {} and symbol: {}", id, symbol);
从上述描述中可以看出，阿里强制要求在日志输出时必须使用占位符的方式进行字符串拼接，因为这样可以有效的提高程序的性能。
然而当我们使用 Oracle 官方提供的 JMH（Java Microbenchmark Harness，JAVA 微基准测试套件）框架来测试时，却发现结果和手册上描述的完全不一样。
PS：对 JMH 不熟悉的朋友，可以看我发布的另一篇文章《Oracle官方推荐的性能测试工具！简单、精准又直观！》
性能测试
本文我们借助 Spring Boot 2.2.6 来完成测试，首先我们先在 Spring Boot 的 pom.xml 中添加 JMH 框架的依赖：
<!-- https://mvnrepository.com/artifact/org.openjdk.jmh/jmh-core --> <dependency> <groupId>org.openjdk.jmh</groupId> <artifactId>jmh-core</artifactId> <version>1.23</version> </dependency> <!-- https://mvnrepository.com/artifact/org.openjdk.jmh/jmh-generator-annprocess --> <dependency> <groupId>org.openjdk.jmh</groupId> <artifactId>jmh-generator-annprocess</artifactId> <version>1.23</version> <scope>provided</scope> </dependency>
这里需要注意一下，一般的项目我们只需要添加 jmh-core 的依赖包就可以了，但如果是 Spring Boot 项目的话，我们还必须添加 jmh-generator-annprocess 包依赖，并且要把 scope 设置为 provided 类型，如果使用它的默认值 test 就会导致程序报错 Unable to find the resource: /META-INF/BenchmarkList。
scope 值说明：
- compile：默认值，它表示被依赖项目需要参与当前项目的编译、测试和运行等阶段，在打包时通常也需要添加进去；
- test：表示依赖项目仅仅参与测试相关的工作，在编译和运行环境下都不会被使用，更别说打包了；
- provided：适用于编译和测试的阶段，他不会被打包到 lib 目录下；
- runntime：仅仅适用于运行环境，在编译和测试环境下都不会被使用。
紧接着，我们编写了完整的测试代码：
import org.openjdk.jmh.annotations.*; import org.openjdk.jmh.runner.Runner; import org.openjdk.jmh.runner.RunnerException; import org.openjdk.jmh.runner.options.Options; import org.openjdk.jmh.runner.options.OptionsBuilder; import org.slf4j.Logger; import org.slf4j.LoggerFactory; import org.springframework.web.bind.annotation.RequestMapping; import org.springframework.web.bind.annotation.RestController; import java.util.concurrent.TimeUnit; @BenchmarkMode(Mode.AverageTime) // 测试完成时间 @OutputTimeUnit(TimeUnit.NANOSECONDS) @Warmup(iterations = 2, time = 1, timeUnit = TimeUnit.SECONDS) // 预热 2 轮，每次 1s @Measurement(iterations = 5, time = 3, timeUnit = TimeUnit.SECONDS) // 测试 5 轮，每次 3s @Fork(1) // fork 1 个线程 @State(Scope.Thread) // 每个测试线程一个实例 @RestController @RequestMapping("/log") public class LogPrint { private final Logger log = LoggerFactory.getLogger(LogPrint.class); private final static int MAX_FOR_COUNT = 100; // for 循环次数 public static void main(String[] args) throws RunnerException { // 启动基准测试 Options opt = new OptionsBuilder() .include(LogPrint.class.getName() + ".*") // 要导入的测试类 .build(); new Runner(opt).run(); // 执行测试 } @Benchmark public void appendLogPrint() { for (int i = 0; i < MAX_FOR_COUNT; i++) { // 循环的意图是为了放大性能测试效果 StringBuilder sb = new StringBuilder(); sb.append("Hello, "); sb.append("Java"); sb.append("."); sb.append("Hello, "); sb.append("Redis"); sb.append("."); sb.append("Hello, "); sb.append("MySQL"); sb.append("."); log.info(sb.toString()); } } @Benchmark public void logPrint() { for (int i = 0; i < MAX_FOR_COUNT; i++) { // 循环的意图是为了放大性能测试效果 log.info("Hello, {}.Hello, {}.Hello, {}.", "Java", "Redis", "MySQL"); } } }
测试结果如下：
从上述结果可以看出直接使用 StringBuilder 拼接的方式显然要比使用占位符的方式性能要高，难道是我搞错了？
备注：测试环境为 Spring Boot 2.2.6 RELEASE、JDK 8（JDK 1.8.0_10）、MacOS（MacMini 2018）
源码分析
抱着怀疑的态度，我们打开了 slf4j 的源码，看看占位符的底层方法到底是如何实现的，于是我就顺着 log.info 方法找到了占位符最终的实现源码：
final public static FormattingTuple arrayFormat(final String messagePattern, final Object[] argArray, Throwable throwable) { if (messagePattern == null) { return new FormattingTuple(null, argArray, throwable); } if (argArray == null) { return new FormattingTuple(messagePattern); } int i = 0; int j; // use string builder for better multicore performance StringBuilder sbuf = new StringBuilder(messagePattern.length() + 50); int L; // for 循环替换占位符 for (L = 0; L < argArray.length; L++) { j = messagePattern.indexOf(DELIM_STR, i); if (j == -1) { // no more variables if (i == 0) { // this is a simple string return new FormattingTuple(messagePattern, argArray, throwable); } else { // add the tail string which contains no variables and return // the result. sbuf.append(messagePattern, i, messagePattern.length()); return new FormattingTuple(sbuf.toString(), argArray, throwable); } } else { if (isEscapedDelimeter(messagePattern, j)) { if (!isDoubleEscaped(messagePattern, j)) { L--; // DELIM_START was escaped, thus should not be incremented sbuf.append(messagePattern, i, j - 1); sbuf.append(DELIM_START); i = j + 1; } else { // The escape character preceding the delimiter start is // itself escaped: "abc x:\\{}" // we have to consume one backward slash sbuf.append(messagePattern, i, j - 1); deeplyAppendParameter(sbuf, argArray[L], new HashMap<Object[], Object>()); i = j + 2; } } else { // normal case sbuf.append(messagePattern, i, j); deeplyAppendParameter(sbuf, argArray[L], new HashMap<Object[], Object>()); i = j + 2; } } } // append the characters following the last {} pair. sbuf.append(messagePattern, i, messagePattern.length()); return new FormattingTuple(sbuf.toString(), argArray, throwable); }
从上述源码可以看出，所谓的占位符其实底层也是使用 StringBuilder 来实现的，怪不得性能不如直接使用 StringBuilder。因为在进行占位符替换的时候，还经过了一些列的验证才进行替换的，而直接使用 StringBuilder 则可以省去这部分效验的工作。
为了保证我没有搞错，于是我使用 Idea 开启了调试模式，调试的结果如下图所示：
从上图可以看出，此方法就是占位符的实际执行方法，那也就是说，手册上写的性能问题确实是错的。
于是我就随手发了一个朋友圈：
却发现在审纸质书的编辑也恰好是我的好友：
这样就可以避免这个问题，会直接出现在未来的纸质书中，也算是功劳一件了。
