Java 8보다 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"
더 구체적으로, I am running Microsoft Windows [Version 10.0.17763.195].
CPU 시간이 소비되는 곳을 보여주는 멋진 불꽃 그래프를 그릴 수 있는 async-profiler로 문제를 조사했습니다 .
@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에서는 훨씬 더 오래 걸립니다.
확대 해 보겠습니다.
Note that StringTable::intern in JDK 11 calls do_intern which in turn allocates a new java.lang.String object. Looks suspicious. Nothing of this kind is seen in JDK 10 profile. Time to look in the source code.
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);
}
The function in JDK 11 first looks for a string in the shared StringTable, does not find it, then goes to do_intern and immediately creates a new String object.
In JDK 10 sources after a call to lookup_shared there was an additional lookup in the main table which returned the existing string without creation of a new object:
found_string = the_table()->lookup_in_main_table(index, name, len, hashValue);
This refactoring was a result of JDK-8195097 "Make it possible to process StringTable outside safepoint".
TL;DR While interning method names in JDK 11, HotSpot creates redundant String objects. This has happened after JDK-8195097.
I suspect this is due to several changes.
8->9 regression happened while switching to StackWalker for generating the stack traces (JDK-8150778). Unfortunately, this made VM native code intern a lot of strings, and StringTable becomes the bottleneck. If you profile OP's benchmark, you will see the profile like in JDK-8151751. It should be enough to perf record -g the entire JVM that runs the benchmark, and then look into perf report. (Hint, hint, you can do it yourself next time!)
And 10->11 regression must have happened later. I suspect this is due to StringTable preparations for switching to fully concurrent hash table (JDK-8195100, which, as Claes points out, is not entirely in 11) or something else (class data sharing changes?).
Either way, interning on fast path is a bad idea, and patch for JDK-8151751 should have dealt with both regressions.
Watch this:
8u191: 15108 ± 99 ns/op [so far so good]
- 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
"head": 22382 ± 134 ns/op [regression]
- 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 patch: 7511 ± 26 ns/op [woot, even better than 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
ReferenceURL : https://stackoverflow.com/questions/53961275/java-11-performance-regressions-against-java-8
'programing' 카테고리의 다른 글
| 프로그래머가 아닌 사람에게 프로젝트 복잡성을 설명하는 좋은 은유가 있습니까? (0) | 2021.01.16 |
|---|---|
| C의 삼항 (조건부) 연산자 (0) | 2021.01.16 |
| MPVolumeView를 사용한 후 시스템 볼륨 오버레이를 다시 켜려면 어떻게합니까? (0) | 2021.01.16 |
| RApacheOutputErrors로 출력 제어 (0) | 2021.01.16 |
| 무결성 수준이 일치하지 않는 .NET COM 서버에 대한 연결 허용 (0) | 2021.01.16 |