阿里《Java开发手册》也有bug？

时间 2020-06-09

原文原文链接

原本打算写一篇《阿里巴巴为何不容许日志输出时，使用字符串拼接？》的文章，主要是想从性能方面来讲此问题，可在文章写到一半进行性能测试时，却发现了一个异常问题，实际测试的结果和手册上描述的结果是截然相反的！java

天撸了，怎么会发生这种事情？此时个人心里是拒绝的，由于文章已经写了一半了啊，这让我瞬间陷入了尴尬的境地。web

阿里巴巴的《Java开发手册》泰山版（最新版）是这样描述的，它在第二章第三小节的第 4 条规范中指出：spring

【强制】在日志输出时，字符串变量之间的拼接使用占位符的方式。
说明：由于 String 字符串的拼接会使用 StringBuilder 的 append() 方式，有必定的性能损耗。使用占位符仅是替换动做，能够有效提高性能。api

正例：logger.debug("Processing trade with id: {} and symbol: {}", id, symbol);网络

从上述描述中能够看出，阿里强制要求在日志输出时必须使用占位符的方式进行字符串拼接，由于这样能够有效的提升程序的性能。app

然而当咱们使用 Oracle 官方提供的 JMH（Java Microbenchmark Harness，JAVA 微基准测试套件）框架来测试时，却发现结果和手册上描述的彻底不同。框架

PS：对 JMH 不熟悉的朋友，能够看我发布的另外一篇文章《Oracle官方推荐的性能测试工具！简单、精准又直观！》ide

性能测试

本文咱们借助 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 开启了调试模式，调试的结果以下图所示：

从上图能够看出，此方法就是占位符的实际执行方法，那也就是说，手册上写的性能问题确实是错的。

因而我就随手发了一个朋友圈：

却发如今写纸质书的编辑也刚好是个人好友：

这样就能够避免这个问题，会直接出如今将来的纸质书中，也算是功劳一件了。

扩展篇

咱们在 Spring Boot 中使用日志一般会这样写：

private final Logger log = LoggerFactory.getLogger(LogPrint.class);

而且每一个类中都要写这样一行代码，未免有些麻烦。

此时咱们可使用 @Slf4j 注解来替代上面的那行 Logger 对象建立的代码，完整使用示例以下：

import lombok.extern.slf4j.Slf4j;
import org.junit.jupiter.api.Test;

@Slf4j
class LogTest {
    @Test
    void show() {
        log.debug("Hello, {}.", "Debug");
        log.info("Hello, {}.", "Info");
        log.error("Hello, {}.", "Error");
    }
}

程序的执行结果：

14:33:18.377 [main] DEBUG com.example.demo.LogTestTest - Hello, Debug.
14:33:18.382 [main] INFO com.example.demo.LogTestTest - Hello, Info.

14:33:18.382 [main] ERROR com.example.demo.LogTestTest - Hello, Error.

从上述结果能够看出，日志已经正常输出到控制台了。

注意：@Slf4j 注解属于 lombok，所以要想在项目中使用 @Slf4j 注解，须要保证项目中已经添加了 lombok 的依赖。

总结

在进行日志输出时，字符串变量之间的拼接要使用占位符的方式，由于这样写会比较优雅。咱们查了 slf4j 的源码发现，占位符的底层也是经过 StringBuilder 拼接来实现的。

旧文章：

为了响应国家“低碳生活，绿色出行”的号召，老王决定之后要骑自行车上下班，不但省钱并且还不堵车，最主要的是能为国家出一份力。为了达成这个目标，老王 happy 的掏出了他的诺基亚老年机，一顿操做在某宝买了一辆 8 成新的二八自行车，幻想着今后能过上了幸福生活。
但车子买回来以后却发现，村东头已经放满了 2 元钱就能骑一个月的共享自行车，你说气人不？不但如此，老王还发现本身买回来的车子不只很差骑，还不支持七天无理由退货，这给老王气的，回手就是一个五星差评。

在看卖家这边，反而一点都不着急，只是冷冷的给回了一句：小子，我还怕你？这月干完我就全职摆地摊了，网店反正也不开了，差评就差评呗。

这个故事深入告诉咱们一个道理：若是别人已经给咱们提供好了“自行车”，那咱们就不用本身花钱再卖一个了。

（该图片来源于网络）

看到这里有人可能会问了：小伙子，你这是正经的技术文章不？你说的这些和技术有毛关系啊？

这个故事和今天的主题还真有关系，下面咱们正式开始...