阿里《Java开发手册》中的 1 个bug！

阳光穿透心脏的1/2处 2023-10-06 10:29 9阅读 0赞

![format_png][]

这是我的第 210 期分享

作者 | 王磊

来源 | Java中文社群（ID：javacn666）

转载请联系授权（微信ID：GG\_Stone）

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

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

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

> 【强制】在日志输出时，字符串变量之间的拼接使用占位符的方式。
> 
> 说明：因为 String 字符串的拼接会使用 StringBuilder 的 append() 方式，有一定的性能损耗。使用占位符仅 是替换动作，可以有效提升**性能**。
> 
> 正例：logger.debug("Processing trade with id: \{\} and symbol: \{\}", id, symbol);

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

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

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

### 性能测试 ###

本文我们借助 Spring Boot 2.2.6 来完成测试，首先我们先在 Spring Boot 的 pom.xml 中添加 JMH 框架的依赖：

<dependency>
      <groupId>org.openjdk.jmh</groupId>
      <artifactId>jmh-core</artifactId>
      <version>1.23</version>
    </dependency>
    
    <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");
            }
        }
    }

测试结果如下：

![format_png 1][]

从上述结果可以看出直接使用 `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 开启了调试模式，调试的结果如下图所示：

![format_png 2][]

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

于是我就随手发了一个朋友圈：

![format_png 3][]

却发现在审纸质书的编辑也恰好是我的好友：

![format_png 4][]

这样就可以避免这个问题，会直接出现在未来的纸质书中，也算是功劳一件了。

### 扩展篇 ###

我们在 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 元钱就能骑一个月的共享自行车，你说气人不？不但如此，老王还发现自己买回来的车子不仅不好骑，还不支持七天无理由退货，这给老王气的，回手就是一个五星差评。
> 
> 在看卖家这边，反而一点都不着急，只是冷冷的给回了一句：小子，我还怕你？这月干完我就**全职摆地摊了，网店反正也不开了**，差评就差评呗。
> 
> 这个故事深刻告诉我们一个道理：如果别人已经给我们提供好了“自行车”，那我们就不用自己花钱再卖一个了。
> 
> ![format_png 5][]
> 
> 看到这里有人可能会问了：小伙子，你这是正经的技术文章不？你说的这些和技术有毛关系啊？
> 
> 这个故事和今天的主题还真有关系，下面我们正式开始...

往期推荐

[![format_png 6][]][format_png 6 1]

[阿里新版《Java 开发手册(泰山版)》内容解读（附下载地址）][format_png 6 1]

[阿里巴巴为什么让初始化集合时必须指定大小？][Link 1]

关注下方二维码，订阅更多精彩内容

![format_png 7][]

**觉得有用，请点击“在看”！**![format_png 8][]

[format_png]: https://imgconvert.csdnimg.cn/aHR0cHM6Ly9tbWJpei5xcGljLmNuL21tYml6X3BuZy9Icld3Nlp1WENzamtJRkF5c0hSaWFnUUljTXRkbWhkSm1xU290ZnQ4OEFIdWUwU0ZjaWNSNzBRd2VaQXk1aWFUZGlhcTJKQU8yZ2xkQk9FcjZxaE1rVWhmb3cvNjQw?x-oss-process=image/format,png
[Oracle]: https://blog.csdn.net/sufu1065/article/details/106515342
[format_png 1]: https://imgconvert.csdnimg.cn/aHR0cHM6Ly9tbWJpei5xcGljLmNuL21tYml6X3BuZy9Icld3Nlp1WENzZ2hIdzFTNTd5SFI3alpCWmZvTzNmTXpkclVxaWN2eWtGNEc1aGljbXNwcUJQSlNPYUZEaWJpYlBzeXpMSFdXdmt5VzRWMkZ2ODQ1Q1F4T0EvNjQw?x-oss-process=image/format,png
[format_png 2]: https://imgconvert.csdnimg.cn/aHR0cHM6Ly9tbWJpei5xcGljLmNuL21tYml6X3BuZy9Icld3Nlp1WENzZ2hIdzFTNTd5SFI3alpCWmZvTzNmTUQ4MW10MUdkYTNPaWJxVmljWTBOYm9wV095QlNhdVFZcFFERzhpY29YNmFuWHRwdWRBQjNKNUxlQS82NDA?x-oss-process=image/format,png
[format_png 3]: https://imgconvert.csdnimg.cn/aHR0cHM6Ly9tbWJpei5xcGljLmNuL21tYml6X3BuZy9Icld3Nlp1WENzZ2hIdzFTNTd5SFI3alpCWmZvTzNmTWVGa2dZbEVGZVFIeGxYTU50d3JIOUFZRGFwTzQ1SVpSVGh2NHJyUTFOWGdtTkNrMXdWOU9Ndy82NDA?x-oss-process=image/format,png
[format_png 4]: https://imgconvert.csdnimg.cn/aHR0cHM6Ly9tbWJpei5xcGljLmNuL21tYml6X3BuZy9Icld3Nlp1WENzZ2hIdzFTNTd5SFI3alpCWmZvTzNmTTF5SmFkUVNoOXk4eVpXalJpYXRFZWRwbUphM09XRTRMdXg2WFJsdHUweDNLMHdGeFAwVlBmRkEvNjQw?x-oss-process=image/format,png
[format_png 5]: https://imgconvert.csdnimg.cn/aHR0cHM6Ly9tbWJpei5xcGljLmNuL21tYml6X3BuZy9Icld3Nlp1WENzZ2hIdzFTNTd5SFI3alpCWmZvTzNmTVZHckVWTjRtcjNtZ0xGUHBWNUpBRXpQVkNTQXF0dDNUdkRpYjJySWM2Rm1jYlFFUHNtVVEwencvNjQw?x-oss-process=image/format,png
[format_png 6]: https://imgconvert.csdnimg.cn/aHR0cHM6Ly9tbWJpei5xcGljLmNuL21tYml6X2pwZy9Icld3Nlp1WENzaWF5YktCWGliM1NxU2lidmpTcVJzSUE5SlhSUEU3WEhPeGY1Y0xCUTQ4WE5Ub3hDelEyWkk3T2lidXVBdFNLVkNpYnBxR3BDaE9QUGlhZU1Fdy82NDA?x-oss-process=image/format,png
[format_png 6 1]: http://mp.weixin.qq.com/s?__biz=MzU1NTkwODE4Mw%3D%3D&chksm=fbcc6bfbccbbe2ed2dbd1edf19a480930b6008a17230cec3a3556d8892bb747d0ab2d1cbefbe&idx=1&mid=2247485123&scene=21&sn=ba7292b22daedcd8b69e7cf49357c115#wechat_redirect
[Link 1]: https://blog.csdn.net/sufu1065/article/details/106435853
[format_png 7]: https://imgconvert.csdnimg.cn/aHR0cHM6Ly9tbWJpei5xcGljLmNuL21tYml6X2pwZy9zWnlBSnRpYWVzV2NqajRZNmIyUnNZampPNGNtc0E3OXZKY2RyY080RDZxb2t6V1l6NjQ4S2ZQVFNsSWhCeWVKbGZzQmtLaWFzWHR4a2JSTFRUSUxRcGlidy82NDA?x-oss-process=image/format,png
[format_png 8]: https://imgconvert.csdnimg.cn/aHR0cHM6Ly9tbWJpei5xcGljLmNuL21tYml6X2dpZi9ub3oyancyaFBsV2lhQ3JHdUp4QmljVTVtY2liM1FhcERMeW82ZUtuTlZtOWRQVFY0WjFTaWNITHRyQ0N3T0c5Z2JsTUJGbEtmN3A5Y3Z3TDZ3SWtaSnZhbWcvNjQw?x-oss-process=image/format,png