写点什么

驳《阿里「Java 开发手册」中的 1 个 bug》?

用户头像
王磊
关注
发布于: 2020 年 06 月 10 日
驳《阿里「Java开发手册」中的1个bug》?

前两天写了一篇关于《阿里Java开发手册中的 1 个bug》的文章,评论区有点炸锅了,基本分为两派,支持老王的和质疑老王的。



首先来说,无论是那一方,我都真诚的感谢你们。特别是「二师兄」,本来是打算周五晚上好好休息一下的(周五晚上发布的文章),结果因为和我讨论这个问题,一直搞到晚上 12 点左右,可以看出,他对技术的那份痴迷。这一点我们是一样的,和阅读本文的你一样,我们属于一类人,一类对技术无限痴迷的人





对与错的意义

其实在准备发这篇文章时,已经预料到这种局面了,当你提出质疑时,无论对错,一定有相反的声音,因为别人也有质疑的权利,而此刻你要做的,就是尽量保持冷静,用客观的态度去理解和验证这些问题。而这些问题(不同的声音)终将成为一笔宝贵的财富,因为你在这个验证的过程中一定会有所收获。



同时我也希望我的理解是错的,因为和大家一样,也是阿里《Java开发手册》的忠实“信徒”,只是意外的窥见了“不同”,然后顺手把自己的思路和成果分享给了大家。



但我也相信,任何“权威”都有犯错的可能,老祖宗曾告诉过我们“人非圣贤孰能无过”。我倒不是非要纠结谁对谁错,相反我认为一味的追求谁对谁错是件非常幼稚的事情,只有小孩子才这样做,我们要做的是通过辩论这件事的“对与错”,学习到更多的知识,帮助我们更好的成长,这才是我今天这篇文章诞生的意义。



乔布斯曾说过:我最喜欢和聪明人一起工作,因为完全不用顾忌他们的尊严。我倒不是聪明人,但我知道任何一件“错事”的背后,一定有它的价值。因此我不怕被“打脸”,如果想要快速成长的话,我劝你也要这样。



好了,就聊这么多,接下来咱们进入今天正题。

反对的声音

持不同看法的朋友的主要观点有以下这些:







我把这些意见整理了一下,其实说的是一件事,我们先来看原文的内容。

在《Java开发手册》泰山版(最新版)的第二章第三小节的第 4 条规范中指出:



【强制】在日志输出时,字符串变量之间的拼接使用占位符的方式。

说明:因为 String 字符串的拼接会使用 StringBuilder 的 append() 方式,有一定的性能损耗。使用占位符仅 是替换动作,可以有效提升性能

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



反对者(注意这个“反对者”不是贬义词,而是为了更好的区分角色)的意思是这样的:



使用占位符会先判断日志的输出级别再决定是否要进行拼接输出,而直接使用 StringBuilder 的方式会先进行拼接再进行判断,这样的话,当日志级别设置的比较高时,因为 StringBuilder 是先拼接再判断的,因此造成系统资源的浪费,所以使用占位符的方式比 StringBuilder 的方式性能要高。



咱先放下反对者说的这个含义在阿里《Java开发手册》中是否有体现,因为我确实没有看出来,咱们先顺着这个思路来证实一下这个结论是否正确。

性能评测

还是老规矩,咱们用数据和代码说话,为了测试 JMH(测试工具)能和 Spring Boot 很好的结合,首先我们要做的就是先测试一下日志输出级别设置,是否能在 JMH 的测试代码中生效。



那么接下来我们先来编写「日志级别设置」的测试代码:

import lombok.extern.slf4j.Slf4j;
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.springframework.boot.SpringApplication;
import java.util.concurrent.TimeUnit;
@BenchmarkMode(Mode.AverageTime) // 测试完成时间
@OutputTimeUnit(TimeUnit.NANOSECONDS)
@Warmup(iterations = 2, time = 2, timeUnit = TimeUnit.SECONDS) // 预热 2 轮,每次 2s
@Measurement(iterations = 5, time = 3, timeUnit = TimeUnit.SECONDS) // 测试 5 轮,每次 3s
@Fork(1) // fork 1 个线程
@State(Scope.Thread) // 每个测试线程一个实例
@Slf4j
public class LogPrintAmend {
public static void main(String[] args) throws RunnerException {
// 启动基准测试
Options opt = new OptionsBuilder()
.include(LogPrintAmend.class.getName() + ".*") // 要导入的测试类
.build();
new Runner(opt).run(); // 执行测试
}
@Setup
public void init() {
// 启动 spring boot
SpringApplication.run(DemoApplication.class);
}
@Benchmark
public void logPrint() {
log.debug("show debug");
log.info("show info");
log.error("show error");
}
}



在测试代码中,我们使用了 3 个级别的日志输出指令:debug 级别、 info 级别和 error 级别。

然后我们再在配置文件(application.properties)中的设置日志的输出级别,配置如下:



logging.level.root=info

可以看出我们把所有的日志输出级别设置成了 info 级别,然后我们执行以上程序,执行结果如下:





从上图中我们可以看出,日志只输出了 infoerror 级别,也就是说我们设置的日志输出级别生效了,为了保证万无一失,我们再把日志的输出级别降为 debug 级别,测试的结果如下图所示:





从上面的结果可以看出,我们设置的日志级别没有任何问题,也就是说,JMH 框架可以很好的搭配 SpringBoot 来使用



小贴士,日志的等级权重为:TRACE < DEBUG < INFO < WARN < ERROR < FATAL



有了上面日志等级的设置基础之后,我们来测试一下,如果先拼接字符串再判断输出的性能和占位符的性能评测结果,完整的测试代码如下:

import lombok.extern.slf4j.Slf4j;
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.springframework.boot.SpringApplication;
import java.util.concurrent.TimeUnit;
@BenchmarkMode(Mode.AverageTime) // 测试完成时间
@OutputTimeUnit(TimeUnit.NANOSECONDS)
@Warmup(iterations = 2, time = 2, timeUnit = TimeUnit.SECONDS) // 预热 2 轮,每次 2s
@Measurement(iterations = 5, time = 3, timeUnit = TimeUnit.SECONDS) // 测试 5 轮,每次 3s
@Fork(1) // fork 1 个线程
@State(Scope.Thread) // 每个测试线程一个实例
@Slf4j
public class LogPrintAmend {
private final static int MAX_FOR_COUNT = 100; // for 循环次数
public static void main(String[] args) throws RunnerException {
// 启动基准测试
Options opt = new OptionsBuilder()
.include(LogPrintAmend.class.getName() + ".*") // 要导入的测试类
.build();
new Runner(opt).run(); // 执行测试
}
@Setup
public void init() {
SpringApplication.run(DemoApplication.class);
}
@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(".");
// 再判断
if (log.isInfoEnabled()) {
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");
}
}
}
复制代码

可以看出代码中使用了 info 的日志数据级别,那么此时我们再将配置文件中的日志级别设置为大于 infoerror 级别,然后执行以上代码,测试结果如下:





哇,测试结果真令人满意。从上面的结果可以看出使用占位符的方式的性能,真的比 StringBuilder 的方式高很多,这就说明阿里的《Java开发手册》说的没问题喽。

反转

但事情并没有那么简单,就比如你正在路上走着,迎面而来了一个自行车,眼看就要撞到你了,此时你会怎么做?毫无疑问你会下意识的躲开。



那么对于上面的那个评测也是一样,为什么要在字符串拼接之后再进行判断呢?



如果编程已经是你的一份正式职业,那么先判断再拼接字符串是最基础的职业技能要求,这和你会下意识的躲开迎面相撞的自行车的道理是一样的,在你完全有能力规避问题的时候,一定是先规避问题,再进行其他操作的,否则在团队 review 代码的时候或者月底裁员的时候时,你一定是首选的“受害”对象了。因为像这么简单的(错误)问题,只有刚入门的新手才可能会出现。



那么按照一个程序最基本的要求,我们应该这样写代码:

import lombok.extern.slf4j.Slf4j;
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.springframework.boot.SpringApplication;
import java.util.concurrent.TimeUnit;
@BenchmarkMode(Mode.AverageTime) // 测试完成时间
@OutputTimeUnit(TimeUnit.NANOSECONDS)
@Warmup(iterations = 2, time = 2, timeUnit = TimeUnit.SECONDS) // 预热 2 轮,每次 2s
@Measurement(iterations = 5, time = 3, timeUnit = TimeUnit.SECONDS) // 测试 5 轮,每次 3s
@Fork(1) // fork 1 个线程
@State(Scope.Thread) // 每个测试线程一个实例
@Slf4j
public class LogPrintAmend {
private final static int MAX_FOR_COUNT = 100; // for 循环次数
public static void main(String[] args) throws RunnerException {
// 启动基准测试
Options opt = new OptionsBuilder()
.include(LogPrintAmend.class.getName() + ".*") // 要导入的测试类
.build();
new Runner(opt).run(); // 执行测试
}
@Setup
public void init() {
SpringApplication.run(DemoApplication.class);
}
@Benchmark
public void appendLogPrint() {
for (int i = 0; i < MAX_FOR_COUNT; i++) { // 循环的意图是为了放大性能测试效果
// 再判断
if (log.isInfoEnabled()) {
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");
}
}
}

甚至是把 if 判断提到 for 循环外,但本文的 for 不代表具体的业务,而是为了更好的放大测试效果而写的代码,因此我们会把判断写到 for 循环内。



那么此时我们再来执行测试的代码,执行结果如下图所示:





从上述结果可以看出,使用先判断再拼接字符串的方式还是要比使用占位符的方式性能要高。



那么,我们依然没有办法证明阿里《Java开发手册》中的占位符性能高的结论



所以我依旧保持我的看法,使用占位符而非字符串拼接,主要可以保证代码的优雅性,可以在代码中少些一些逻辑判断,但这样写和性能无关

扩展知识:格式化日志

在上面的评测过程中,我们发现日志的输出格式非常“乱”,那有没有办法可以格式化日志呢?

答案是:有的,默认日志的输出效果如下:

格式化日志可以通过配置 Spring Boot 中的 logging.pattern.console 选项实现的,配置示例如下:

logging.pattern.console=%d | %msg %n

日志的输出结果如下:

可以看出,格式化日志之后,内容简洁多了,但千万不能因为简洁,而遗漏输出关键性的调试信息。

总结

本文我们测试了读者提出质疑的字符串拼接和占位符的性能评测,发现占位符方式性能高的观点依然无从考证,所以我们的基本看法还是,使用占位符的方式更加优雅,可以通过更少的代码实现更多的功能;至于性能方面,只能说还不错,但不能说很优秀。在文章的最后我们讲了 Spring Boot 日志格式化的知识,希望本文可以切实的帮助到你,也欢迎你在评论区留言和我互动。

最后的话

原创不易,都看到这了,点个「」再走呗,这是对我最大的支持与鼓励,谢谢你!

用户头像

王磊

关注

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

公众号:Java中文社群

评论 (11 条评论)

发布
用户头像
字符串拼接的代码多难维护呀,牺牲一点点性能换来更好的可读性有什么错呢?现代服务器不差那点性能。真的性能要求严格的地方,你只要写日志就撑不住的拉。
2020 年 06 月 15 日 15:34
回复
确实是这样。
2020 年 07 月 27 日 19:53
回复
用户头像
无语,看下代码不就知道了吗。。。。。 ?
2020 年 06 月 15 日 14:56
回复
用户头像
重新去看了下 第日志规范的第4条和第5条 ,因为有第5条的存在 ,所有否定定参数先计算的问题 , 我个人理解 ,日志场景 ,我们通常有一种常用写法 logger.debug("Processing trade with id " + id + " and symbol: " + symbol") ,因为这种 + 默认实现方法低效,所有不建议使用这种,建议使用拼接占位符 ,这里应该描述的是这个场景 。我想实际场景的人,应该没人会使用 StringBuffer 这种 append 记录日志吧。 手册上,这句话确实可以改下,不是StringBuffer的锅,是 + 的锅,另外需要举个反例 ,应该就没这种问题了
2020 年 06 月 14 日 09:06
回复
+的编译结果就是stringbuilder拼接,说的没问题
2020 年 07 月 22 日 22:08
回复
用户头像
感觉有些争论不在同一场景下。同步一下。
java方法调用之前,先要完成参数的准备,如果是表达式需要求解表达式的值。
所以这就引出了手册与部分评论者的观点,使用占位符会得到更好的性能。原因大家也清楚,占位符情况下,打印日志的方法参数是简单引用,一般不会再使用表达式。
其实手册没有给出不使用占位符的反例,所以大家对于这点产生了分歧。手册和部分评论者比较的对象应该是指打印日志方法参数是某种拼接字符串的表达式。以这种场景为反例,那么手册中的观点就成立了。
本文作者也做了这种场景的测试(在调用打印日志方法前,用StringBuilder拼接好字符串),而且也分析了这种观念方法性能差的原因(受日志级别的影响,之前因为拼接字符串导致的消耗可能是无意义的)。
但是作者认为从手册中的表述出发,并不局限于这一场景。而是在比较字符串替换与StringBuilder拼接的性能。所以有了后面的测试,让StringBuilder拼接的方案在相应loglevel被禁用的情况下无需执行拼接动作,这一点与占位符方案一致,从而让测试仅仅比较拼接与占位符的性能损耗。得到了最终的结论(拼接要略忧于占位符)。
手册的结论与最终结论相反,这是作者想要强调的一点。但个人认为手册中指的应该是前面一种场景,但是手册的用词确实容易让人产生歧义,如手册强调了StringBuidler的append与字符串替换的性能比较。
作者做了详实的实验来支撑自己的观点,值得肯定。不过作者也应该能理解手册想要表达的主要意思,以bug冠名,有点抢眼球的意思了。
展开
2020 年 06 月 12 日 10:22
回复
用户头像
抛开实际的工程实践搞测试的行为就是耍流氓。
先说结论:就最初的测试,把日志打印级别调整到 WARN 以上,再跑下 benchmark 看下结果?
再说原因:在这篇文章里面也谈到了,对于性能的考量,就是在日志打印的时候,是“先判断是否要输出日志,再进行拼接”,还是“先拼接,再判断是否要打印日志”的问题。在你的测试里面,根本就没有测试“是否要打印日志”这个重要的条件。强制让日志给打印出来了,当然是 append 的方式更快,因为需要做的检查少啊。。。
实际的工程里,如果使用 log.debug("hello, " + "java") 的方式来输出日志,无论部署时日志级别时的设置的是什么,字符串的的拼接都会被执行,如果内容很多的话,会对系统性能造成较大影响,而通过 log.debug("hello, {}", "java") 的方式,就能很好地避免这个问题。如果谁故意通过 appendLogPrint() 这样的方式来打印日志,无论是否加了 isInfoEnabled()
判断,都我会毫不犹豫开掉他,这属于故意搞事情行为。。。
最后吐槽一下,《Java开发手册》中关于这一点的说明确实没说到点上。。。
展开
2020 年 06 月 11 日 11:01
回复
用户头像
按照手册内容来说,并没有体现日志输出级别的含义;个人觉得,手册内容应该是指在同等条件下(日志级别),使用占位符的日志内容最终是通过String.format,实现原理就是字符串替换;而类似于log.debug("Hello,"+"World")这种方式,走的是StringBuilder的append,由于StringBuilder的append方式涉及到扩容和字符串拷贝,在通常情况下,这种方式的性能损耗大会于占位符。
2020 年 06 月 11 日 09:44
回复
用户头像
"因为 String 字符串的拼接会使用 StringBuilder 的 append() 方式,有一定的性能损耗。使用占位符仅 是替换动作,可以有效提升性能" ---- 后半句不是一个明显的表述歧义/错误吗?看来仔细看阿ja手册的不多嘛
2020 年 06 月 11 日 00:01
回复
用户头像
这样比较没有意义,如果是先进行log.isInfoEnabled()判断,那占位符也应该判断,处理逻辑都相同,那还有什么比较的意义?
在正常开发中,是不会进行log.isInfoEnabled()判断的,此时才体现出占位符的优势。
2020 年 06 月 10 日 19:26
回复
用户头像
印象中看过 log4j 2的文档,里面说的是 占位符是延迟拼接 比 debug(“aaa=”+aaa) 效率高,是因为如果不输出debug,后一种方法也会做字符串拼接 ,说的是这种场景。
2020 年 06 月 10 日 19:08
回复
没有更多了
驳《阿里「Java开发手册」中的1个bug》?