performance - El consumo de trazas de la pila es notablemente más lento en Java 11 que en Java 8

java-8 java-11

Question

Estaba comparando el rendimiento de JDK 8 y 11 utilizando jmh 1.21 cuando encontré algunos números sorprendentes:

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 y 12 se comportan de forma similar a OracleJDK 11. He omitido sus números por razones de brevedad.

Entiendo que las marcas de microbado no indican el comportamiento de desempeño de las aplicaciones de la vida real. Aun así, tengo curiosidad por saber de dónde viene esta diferencia. ¿Algunas ideas?

Aquí está el punto de referencia en su totalidad:

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());
}
}
}

Aquí está el script específico de Windows que uso. Debería ser trivial traducirlo a otras plataformas:

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

Mi entorno de ejecución es:

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"

Más específicamente, estoy ejecutando Microsoft Windows [Version 10.0.17763.195] .

Answer 1

Investigué el problema con async-profiler que puede dibujar gráficos de llamas frías demostrando dónde se gasta el tiempo de CPU.

Como señaló @AlekseyShipilev, la desaceleración entre JDK 8 y JDK 9 es principalmente el resultado de los cambios de StackWalker. Además, G1 se ha convertido en el GC predeterminado desde JDK 9. Si establecemos explícitamente -XX:+UseParallelGC (predeterminado en JDK 8), las puntuaciones serán ligeramente mejores.

Pero la parte más interesante es la desaceleración en JDK 11.
Esto es lo que muestra async-profiler (SVG pulsable).

La principal diferencia entre dos perfiles es el tamaño del bloque java_lang_Throwable::get_stack_trace_elements , que está dominado por StringTable::intern . Aparentemente, StringTable::intern toma mucho más tiempo en JDK 11.

Vamos a hacer zoom en:

Tenga en cuenta que StringTable::intern en JDK 11 llama a do_intern que a su vez asigna un nuevo objeto java.lang.String . Parece sospechoso. Nada de este tipo se ve en el perfil JDK 10. Es hora de buscar en el código fuente.

stringTable.cpp (JDK 11)

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);
}

La función en JDK 11 primero busca una cadena en la StringTable compartida, no la encuentra, luego va a do_intern e inmediatamente crea un nuevo objeto String.

En las fuentes de JDK 10 después de una llamada a lookup_shared hubo una búsqueda adicional en la tabla principal que devolvió la cadena existente sin la creación de un nuevo objeto:

 found_string = the_table()->lookup_in_main_table(index, name, len, hashValue);

Esta refactorización fue el resultado de JDK-8195097 "Hacer posible procesar StringTable fuera de un punto de seguridad".

TL; DR Al internar nombres de métodos en JDK 11, HotSpot crea objetos de cadena redundantes. Esto ha sucedido después de JDK-8195097 .

Answer 2

Sospecho que esto se debe a varios cambios.

La regresión 8-> 9 ocurrió mientras se cambiaba a StackWalker para generar las trazas de pila ( bugs.openjdk.java.net/browse/JDK-8150778 ). Desafortunadamente, esto hizo que el código nativo de la máquina virtual fuera un montón de cadenas, y StringTable se convierte en el cuello de botella. Si realiza el perfil de OP, verá el perfil como en bugs.openjdk.java.net/browse/JDK-8151751 . Debería ser suficiente para perf record -g la JVM completa que ejecuta el punto de referencia, y luego ver el perf report . (Pista, pista, ¡puedes hacerlo tú mismo la próxima vez!)

Y la regresión 10-> 11 debe haber ocurrido más tarde. Sospecho que esto se debe a los preparativos de StringTable para cambiar a una tabla hash totalmente concurrente ( JDK-8195100 , que, como señala Claes, no está completamente en 11) o algo más (¿cambios de clase de intercambio de datos?).

De cualquier manera, internarse en una ruta rápida es una mala idea, y el parche para JDK-8151751 debería haber tratado con ambas regresiones.

Ver este:

8u191: 15108 ± 99 ns / op [hasta ahora todo bien]

- 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 

"cabeza": 22382 ± 134 ns / op [regresión]

- 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

Parche "head" + JDK-8151751: 7511 ± 26 ns / op [woot, incluso mejor que 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