写点什么

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

用户头像
王磊
关注
发布于: 2020 年 06 月 08 日
阿里《Java开发手册》也有bug?

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


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


阿里巴巴的《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 开启了调试模式,调试的结果如下图所示:


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

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



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



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

扩展篇

我们在 Spring Boot 中使用日志通常会这样写:

private final Logger log = LoggerFactory.getLogger(LogPrint.class);
复制代码

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

此时我们可以使用 @Slf4j 注解来替代上面的那行 Logger 对象创建的代码,完整使用示例如下:

import lombok.extern.slf4j.Slf4j;import org.junit.jupiter.api.Test;
@Slf4jclass 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 元钱就能骑一个月的共享自行车,你说气人不?不但如此,老王还发现自己买回来的车子不仅不好骑,还不支持七天无理由退货,这给老王气的,回手就是一个五星差评。


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


这个故事深刻告诉我们一个道理:如果别人已经给我们提供好了“自行车”,那我们就不用自己花钱再卖一个了。


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


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


用户头像

王磊

关注

公众号:Java中文社群 2018.08.25 加入

公众号:Java中文社群

评论 (2 条评论)

发布
用户头像
用占位符是为了避免无效拼接,提高性能吧?
2020 年 06 月 08 日 23:24
回复
用户头像
哈哈,bug无处不在
2020 年 06 月 08 日 13:41
回复
没有更多了
阿里《Java开发手册》也有bug?