在Java 11中使用堆栈跟踪的速度明显慢于Java 8
Gil*_*ili 27 performance java-8 jmh java-11
当我遇到一些令人惊讶的数字时,我正在使用jmh 1.21 比较JDK 8和11的性能:
Java version: 1.8.0_192, vendor: Oracle Corporation
Benchmark Mode Cnt Score Error Units
MyBenchmark.throwAndConsumeStacktrace avgt 25 21525.584 ± 58.957 ns/op
Java version: 9.0.4, vendor: Oracle Corporation
Benchmark Mode Cnt Score Error Units
MyBenchmark.throwAndConsumeStacktrace avgt 25 28243.899 ± 498.173 ns/op
Java version: 10.0.2, vendor: Oracle Corporation
Benchmark Mode Cnt Score Error Units
MyBenchmark.throwAndConsumeStacktrace avgt 25 28499.736 ± 215.837 ns/op
Java version: 11.0.1, vendor: Oracle Corporation
Benchmark Mode Cnt Score Error Units
MyBenchmark.throwAndConsumeStacktrace avgt 25 48535.766 ± 2175.753 ns/op
OpenJDK 11和12执行类似于OracleJDK 11.为简洁起见,我省略了它们的数字.
我知道微基准测试并不表示现实应用程序的性能行为.不过,我很好奇这种差异来自哪里.有任何想法吗？
以下是整体基准:
pom.xml:
<project xmlns="http://maven.apache.org/POM/4.0.0" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
xsi:schemaLocation="http://maven.apache.org/POM/4.0.0 http://maven.apache.org/xsd/maven-4.0.0.xsd">
<modelVersion>4.0.0</modelVersion>
<groupId>jmh</groupId>
<artifactId>consume-stacktrace</artifactId>
<version>1.0-SNAPSHOT</version>
<packaging>jar</packaging>
<name>JMH benchmark sample: Java</name>
<dependencies>
<dependency>
<groupId>org.openjdk.jmh</groupId>
<artifactId>jmh-core</artifactId>
<version>${jmh.version}</version>
</dependency>
<dependency>
<groupId>org.openjdk.jmh</groupId>
<artifactId>jmh-generator-annprocess</artifactId>
<version>${jmh.version}</version>
<scope>provided</scope>
</dependency>
</dependencies>
<properties>
<project.build.sourceEncoding>UTF-8</project.build.sourceEncoding>
<jmh.version>1.21</jmh.version>
<javac.target>1.8</javac.target>
<uberjar.name>benchmarks</uberjar.name>
</properties>
<build>
<plugins>
<plugin>
<groupId>org.apache.maven.plugins</groupId>
<artifactId>maven-enforcer-plugin</artifactId>
<version>1.4.1</version>
<executions>
<execution>
<id>enforce-versions</id>
<goals>
<goal>enforce</goal>
</goals>
<configuration>
<rules>
<requireMavenVersion>
<version>3.0</version>
</requireMavenVersion>
</rules>
</configuration>
</execution>
</executions>
</plugin>
<plugin>
<groupId>org.apache.maven.plugins</groupId>
<artifactId>maven-compiler-plugin</artifactId>
<version>3.8.0</version>
<configuration>
<compilerVersion>${javac.target}</compilerVersion>
<source>${javac.target}</source>
<target>${javac.target}</target>
</configuration>
</plugin>
<plugin>
<groupId>org.apache.maven.plugins</groupId>
<artifactId>maven-shade-plugin</artifactId>
<version>3.2.1</version>
<executions>
<execution>
<phase>package</phase>
<goals>
<goal>shade</goal>
</goals>
<configuration>
<finalName>${uberjar.name}</finalName>
<transformers>
<transformer implementation="org.apache.maven.plugins.shade.resource.ManifestResourceTransformer">
<mainClass>org.openjdk.jmh.Main</mainClass>
</transformer>
</transformers>
<filters>
<filter>
<!--
Shading signed JARs will fail without this.
http://stackoverflow.com/questions/999489/invalid-signature-file-when-attempting-to-run-a-jar
-->
<artifact>*:*</artifact>
<excludes>
<exclude>META-INF/*.SF</exclude>
<exclude>META-INF/*.DSA</exclude>
<exclude>META-INF/*.RSA</exclude>
</excludes>
</filter>
</filters>
</configuration>
</execution>
</executions>
</plugin>
</plugins>
<pluginManagement>
<plugins>
<plugin>
<artifactId>maven-clean-plugin</artifactId>
<version>2.6.1</version>
</plugin>
<plugin>
<artifactId>maven-deploy-plugin</artifactId>
<version>2.8.2</version>
</plugin>
<plugin>
<artifactId>maven-install-plugin</artifactId>
<version>2.5.2</version>
</plugin>
<plugin>
<artifactId>maven-jar-plugin</artifactId>
<version>3.1.0</version>
</plugin>
<plugin>
<artifactId>maven-javadoc-plugin</artifactId>
<version>3.0.0</version>
</plugin>
<plugin>
<artifactId>maven-resources-plugin</artifactId>
<version>3.1.0</version>
</plugin>
<plugin>
<artifactId>maven-site-plugin</artifactId>
<version>3.7.1</version>
</plugin>
<plugin>
<artifactId>maven-source-plugin</artifactId>
<version>3.0.1</version>
</plugin>
<plugin>
<artifactId>maven-surefire-plugin</artifactId>
<version>2.22.0</version>
</plugin>
</plugins>
</pluginManagement>
</build>
</project>
src/main/java/jmh/MyBenchmark.java:
package jmh;
import org.openjdk.jmh.annotations.Benchmark;
import org.openjdk.jmh.annotations.BenchmarkMode;
import org.openjdk.jmh.annotations.Mode;
import org.openjdk.jmh.annotations.OutputTimeUnit;
import org.openjdk.jmh.infra.Blackhole;
import java.io.PrintWriter;
import java.io.StringWriter;
import java.util.concurrent.TimeUnit;
@BenchmarkMode(Mode.AverageTime)
@OutputTimeUnit(TimeUnit.NANOSECONDS)
public class MyBenchmark
{
@Benchmark
public void throwAndConsumeStacktrace(Blackhole bh)
{
try
{
throw new IllegalArgumentException("I love benchmarks");
}
catch (IllegalArgumentException e)
{
StringWriter sw = new StringWriter();
e.printStackTrace(new PrintWriter(sw));
bh.consume(sw.toString());
}
}
}
这是我使用的Windows特定脚本.将其转换为其他平台应该是微不足道的:
set JAVA_HOME=C:\Program Files\Java\jdk1.8.0_192
call mvn -V -Djavac.target=1.8 clean install
"%JAVA_HOME%\bin\java" -jar target\benchmarks.jar
set JAVA_HOME=C:\Program Files\Java\jdk-9.0.4
call mvn -V -Djavac.target=9 clean install
"%JAVA_HOME%\bin\java" -jar target\benchmarks.jar
set JAVA_HOME=C:\Program Files\Java\jdk-10.0.2
call mvn -V -Djavac.target=10 clean install
"%JAVA_HOME%\bin\java" -jar target\benchmarks.jar
set JAVA_HOME=C:\Program Files\Java\oracle-11.0.1
call mvn -V -Djavac.target=11 clean install
"%JAVA_HOME%\bin\java" -jar target\benchmarks.jar
我的运行时环境是:
Apache Maven 3.6.0 (97c98ec64a1fdfee7767ce5ffb20918da4f719f3; 2018-10-24T14:41:47-04:00)
Maven home: C:\Program Files\apache-maven-3.6.0\bin\..
Default locale: en_CA, platform encoding: Cp1252
OS name: "windows 10", version: "10.0", arch: "amd64", family: "windows"
更具体地说,我正在跑步Microsoft Windows [Version 10.0.17763.195].
apa*_*gin 38
我用async-profiler调查了这个问题,它可以绘制酷炫的火焰图,展示CPU时间的消耗.
正如@AlekseyShipilev指出的那样,JDK 8和JDK 9之间的放缓主要是StackWalker更改的结果.此外,G1已成为自JDK 9以来的默认GC.如果我们明确设置-XX:+UseParallelGC(默认为JDK 8),则分数会略好一些.
但最有趣的部分是JDK 11的减速.
这是async-profiler显示的内容(可点击的SVG).
两个配置文件之间的主要区别在于java_lang_Throwable::get_stack_trace_elements块的大小,其主要由StringTable::intern.StringTable::internJDK 11 显然需要更长的时间.
我们放大:
请注意,StringTable::intern在JDK 11调用中do_intern,这些调用又分配了一个新java.lang.String对象.看起来很可疑.在JDK 10配置文件中看不到任何此类内容.是时候查看源代码了.
oop StringTable::intern(Handle string_or_null_h, jchar* name, int len, TRAPS) {
// shared table always uses java_lang_String::hash_code
unsigned int hash = java_lang_String::hash_code(name, len);
oop found_string = StringTable::the_table()->lookup_shared(name, len, hash);
if (found_string != NULL) {
return found_string;
}
if (StringTable::_alt_hash) {
hash = hash_string(name, len, true);
}
return StringTable::the_table()->do_intern(string_or_null_h, name, len,
| hash, CHECK_NULL);
} |
----------------
|
v
oop StringTable::do_intern(Handle string_or_null_h, const jchar* name,
int len, uintx hash, TRAPS) {
HandleMark hm(THREAD); // cleanup strings created
Handle string_h;
if (!string_or_null_h.is_null()) {
string_h = string_or_null_h;
} else {
string_h = java_lang_String::create_from_unicode(name, len, CHECK_NULL);
}
JDK 11中的函数首先在共享StringTable中查找字符串,找不到它,然后转到do_intern并立即创建一个新的String对象.
在JDK 10源代码中调用之后lookup_shared,在主表中进行了额外的查找,返回现有字符串而不创建新对象:
found_string = the_table()->lookup_in_main_table(index, name, len, hashValue);
这种重构是JDK-8195097 "可以在安全点之外处理StringTable"的结果.
TL; DR在JDK 11中实习方法名称时,HotSpot会创建冗余的String对象.这发生在JDK-8195097之后.
- 太好了!我做了一个快速的实验,通过在调用`do_intern`之前使用`jchar*`添加回来在微基准测试中获得1.33倍的加速,提交了https://bugs.openjdk.java.net/browse/JDK-8216049引用你的答案. (4认同)
Ale*_*lev 30
我怀疑这是由于一些变化.
在切换到StackWalker以生成堆栈跟踪(JDK-8150778)时发生了8-> 9回归.不幸的是,这使得VM本机代码实习生有很多字符串,而StringTable成为了瓶颈.如果您了解OP的基准,您将看到JDK-8151751中的配置文件.它应该足以perf record -g运行基准测试的整个JVM,然后再研究一下perf report.(提示,提示,下次你可以自己做!)
并且10-> 11回归必定发生在以后.我怀疑这是由于StringTable准备切换到完全并发哈希表(JDK-8195100,正如Claes指出的那样,不完全是11)或其他东西(类数据共享更改？).
无论哪种方式,快速路径上的实习都是一个坏主意,JDK-8151751的补丁应该处理两个回归.
看这个:
8u191:15108±99 ns/op [到目前为止一直很好]
- 54.55% 0.37% java libjvm.so [.] JVM_GetStackTraceElement
- 54.18% JVM_GetStackTraceElement
- 52.22% java_lang_Throwable::get_stack_trace_element
- 48.23% java_lang_StackTraceElement::create
- 17.82% StringTable::intern
- 13.92% StringTable::intern
- 4.83% Klass::external_name
+ 3.41% Method::line_number_from_bci
"头":22382±134 ns/op [回归]
- 69.79% 0.05% org.sample.MyBe libjvm.so [.] JVM_InitStackTraceElement
- 69.73% JVM_InitStackTraceElementArray
- 69.14% java_lang_Throwable::get_stack_trace_elements
- 66.86% java_lang_StackTraceElement::fill_in
- 38.48% StringTable::intern
- 21.81% StringTable::intern
- 2.21% Klass::external_name
1.82% Method::line_number_from_bci
0.97% AccessInternal::PostRuntimeDispatch<G1BarrierSet::AccessBarrier<573
"head"+ JDK-8151751补丁:7511±26 ns/op [woot,甚至优于8u]
- 22.53% 0.12% org.sample.MyBe libjvm.so [.] JVM_InitStackTraceElement
- 22.40% JVM_InitStackTraceElementArray
- 20.25% java_lang_Throwable::get_stack_trace_elements
- 12.69% java_lang_StackTraceElement::fill_in
+ 6.86% Method::line_number_from_bci
2.08% AccessInternal::PostRuntimeDispatch<G1BarrierSet::AccessBarrier
2.24% InstanceKlass::method_with_orig_idnum
1.03% Handle::Handle
- 这个答案涉及本机JVM代码中的瓶颈,因此它使用了vanilla Linux perf,它可以在任何现代Linux发行版上运行.虽然确切的答案确实需要专业知识和经验,但您仍然可以通过使用适当的工具获得*非常接近*的答案,并且还可以节省其他人到达那里的时间.也就是说,询问"配置文件中的这些差异是什么？" 提出"为什么表现不同？"是提升水平的？ (4认同)
- +1.我想我找到了[根本原因](/sf/answers/3781096511/)(评论太长了).你对StringTable准备的假设非常正确. (2认同)
| 归档时间： |
|
| 查看次数： |
2251 次 |
| 最近记录： |