Jmh указывает, что M1 быстрее, чем M2, но M1 делегирует M2
Я написал тест JMH, включающий 2 метода: M1 и M2. M1 вызывает M2, но по какой-то причине JMH утверждает, что M1 быстрее, чем M2.
Вот исходный код:
import java.util.concurrent.TimeUnit;
import static org.bitbucket.cowwoc.requirements.Requirements.assertThat;
import static org.bitbucket.cowwoc.requirements.Requirements.requireThat;
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.runner.Runner;
import org.openjdk.jmh.runner.RunnerException;
import org.openjdk.jmh.runner.options.Options;
import org.openjdk.jmh.runner.options.OptionsBuilder;
@BenchmarkMode(Mode.AverageTime)
@OutputTimeUnit(TimeUnit.NANOSECONDS)
public class MyBenchmark {
@Benchmark
public void assertMethod() {
assertThat("value", "name").isNotNull().isNotEmpty();
}
@Benchmark
public void requireMethod() {
requireThat("value", "name").isNotNull().isNotEmpty();
}
public static void main(String[] args) throws RunnerException {
Options opt = new OptionsBuilder()
.include(MyBenchmark.class.getSimpleName())
.forks(1)
.build();
new Runner(opt).run();
}
}
В приведенном выше примере M1 равен assertThat()
, M2 - requireThat()
. Значение assertThat()
вызывает requireThat()
под капотом.
Вот результат теста:
# JMH 1.13 (released 8 days ago)
# VM version: JDK 1.8.0_102, VM 25.102-b14
# VM invoker: C:\Program Files\Java\jdk1.8.0_102\jre\bin\java.exe
# VM options: -ea
# Warmup: 20 iterations, 1 s each
# Measurement: 20 iterations, 1 s each
# Timeout: 10 min per iteration
# Threads: 1 thread, will synchronize iterations
# Benchmark mode: Average time, time/op
# Benchmark: com.mycompany.jmh.MyBenchmark.assertMethod
# Run progress: 0.00% complete, ETA 00:01:20
# Fork: 1 of 1
# Warmup Iteration 1: 8.268 ns/op
# Warmup Iteration 2: 6.082 ns/op
# Warmup Iteration 3: 4.846 ns/op
# Warmup Iteration 4: 4.854 ns/op
# Warmup Iteration 5: 4.834 ns/op
# Warmup Iteration 6: 4.831 ns/op
# Warmup Iteration 7: 4.815 ns/op
# Warmup Iteration 8: 4.839 ns/op
# Warmup Iteration 9: 4.825 ns/op
# Warmup Iteration 10: 4.812 ns/op
# Warmup Iteration 11: 4.806 ns/op
# Warmup Iteration 12: 4.805 ns/op
# Warmup Iteration 13: 4.802 ns/op
# Warmup Iteration 14: 4.813 ns/op
# Warmup Iteration 15: 4.805 ns/op
# Warmup Iteration 16: 4.818 ns/op
# Warmup Iteration 17: 4.815 ns/op
# Warmup Iteration 18: 4.817 ns/op
# Warmup Iteration 19: 4.812 ns/op
# Warmup Iteration 20: 4.810 ns/op
Iteration 1: 4.805 ns/op
Iteration 2: 4.816 ns/op
Iteration 3: 4.813 ns/op
Iteration 4: 4.938 ns/op
Iteration 5: 5.061 ns/op
Iteration 6: 5.129 ns/op
Iteration 7: 4.828 ns/op
Iteration 8: 4.837 ns/op
Iteration 9: 4.819 ns/op
Iteration 10: 4.815 ns/op
Iteration 11: 4.872 ns/op
Iteration 12: 4.806 ns/op
Iteration 13: 4.811 ns/op
Iteration 14: 4.827 ns/op
Iteration 15: 4.837 ns/op
Iteration 16: 4.842 ns/op
Iteration 17: 4.812 ns/op
Iteration 18: 4.809 ns/op
Iteration 19: 4.806 ns/op
Iteration 20: 4.815 ns/op
Result "assertMethod":
4.855 �(99.9%) 0.077 ns/op [Average]
(min, avg, max) = (4.805, 4.855, 5.129), stdev = 0.088
CI (99.9%): [4.778, 4.932] (assumes normal distribution)
# JMH 1.13 (released 8 days ago)
# VM version: JDK 1.8.0_102, VM 25.102-b14
# VM invoker: C:\Program Files\Java\jdk1.8.0_102\jre\bin\java.exe
# VM options: -ea
# Warmup: 20 iterations, 1 s each
# Measurement: 20 iterations, 1 s each
# Timeout: 10 min per iteration
# Threads: 1 thread, will synchronize iterations
# Benchmark mode: Average time, time/op
# Benchmark: com.mycompany.jmh.MyBenchmark.requireMethod
# Run progress: 50.00% complete, ETA 00:00:40
# Fork: 1 of 1
# Warmup Iteration 1: 7.193 ns/op
# Warmup Iteration 2: 4.835 ns/op
# Warmup Iteration 3: 5.039 ns/op
# Warmup Iteration 4: 5.053 ns/op
# Warmup Iteration 5: 5.077 ns/op
# Warmup Iteration 6: 5.102 ns/op
# Warmup Iteration 7: 5.088 ns/op
# Warmup Iteration 8: 5.109 ns/op
# Warmup Iteration 9: 5.096 ns/op
# Warmup Iteration 10: 5.096 ns/op
# Warmup Iteration 11: 5.091 ns/op
# Warmup Iteration 12: 5.089 ns/op
# Warmup Iteration 13: 5.099 ns/op
# Warmup Iteration 14: 5.097 ns/op
# Warmup Iteration 15: 5.090 ns/op
# Warmup Iteration 16: 5.096 ns/op
# Warmup Iteration 17: 5.088 ns/op
# Warmup Iteration 18: 5.086 ns/op
# Warmup Iteration 19: 5.087 ns/op
# Warmup Iteration 20: 5.097 ns/op
Iteration 1: 5.097 ns/op
Iteration 2: 5.088 ns/op
Iteration 3: 5.092 ns/op
Iteration 4: 5.097 ns/op
Iteration 5: 5.082 ns/op
Iteration 6: 5.089 ns/op
Iteration 7: 5.086 ns/op
Iteration 8: 5.084 ns/op
Iteration 9: 5.090 ns/op
Iteration 10: 5.086 ns/op
Iteration 11: 5.084 ns/op
Iteration 12: 5.088 ns/op
Iteration 13: 5.091 ns/op
Iteration 14: 5.092 ns/op
Iteration 15: 5.085 ns/op
Iteration 16: 5.096 ns/op
Iteration 17: 5.078 ns/op
Iteration 18: 5.125 ns/op
Iteration 19: 5.089 ns/op
Iteration 20: 5.091 ns/op
Result "requireMethod":
5.091 �(99.9%) 0.008 ns/op [Average]
(min, avg, max) = (5.078, 5.091, 5.125), stdev = 0.010
CI (99.9%): [5.082, 5.099] (assumes normal distribution)
# Run complete. Total time: 00:01:21
Benchmark Mode Cnt Score Error Units
MyBenchmark.assertMethod avgt 20 4.855 � 0.077 ns/op
MyBenchmark.requireMethod avgt 20 5.091 � 0.008 ns/op
Чтобы воспроизвести это локально:
У меня есть следующие вопросы:
- Можете ли вы воспроизвести этот результат в конце?
- Что, если что-то не так с эталоном?
UPDATE. Я опубликовал обновленный исходный код исходного кода, результат теста, выход jmh-test и вывод xperfasm в https://bitbucket.org/cowwoc/requirements/downloads за Алексей Шипилев. Я не могу опубликовать их в Stackoverflow из-за ограничения на количество символов в 30 тыс. Слов.
UPDATE2. Наконец, я получаю последовательные и значимые результаты.
Benchmark Mode Cnt Score Error Units
MyBenchmark.assertMethod avgt 60 22.552 ± 0.020 ns/op
MyBenchmark.requireMethod avgt 60 22.411 ± 0.114 ns/op
Под consistent
, я имею в виду, что я получаю почти одинаковые значения в пробегах.
Под meaningful
я имею в виду, что assertMethod()
медленнее, чем requireMethod()
.
Я произвел следующие изменения:
- Блокировка часов процессора (минимальный/максимальный процессор установлен на 99% в Windows Power Options)
- Добавлены опции JVM
-XX:-TieredCompilation -XX:-ProfileInterpreter
Кто-нибудь может достичь этих результатов без удвоения времени выполнения?
UPDATE3. Отключение вставки дает одинаковые результаты без заметного замедления производительности. Я разместил более подробный ответ здесь.
Ответы
Ответ 1
В этом конкретном случае assertMethod
действительно скомпилирован лучше, чем requireMethod
из-за проблем с распределением регистров.
Тест выглядит правильно, и я могу последовательно воспроизводить ваши результаты.
Чтобы проанализировать проблему, я сделал упрощенный тест:
package bench;
import com.google.common.collect.ImmutableMap;
import org.openjdk.jmh.annotations.*;
@State(Scope.Benchmark)
public class Requirements {
private static boolean enabled = true;
private String name = "name";
private String value = "value";
@Benchmark
public Object assertMethod() {
if (enabled)
return requireThat(value, name);
return null;
}
@Benchmark
public Object requireMethod() {
return requireThat(value, name);
}
public static Object requireThat(String parameter, String name) {
if (name.trim().isEmpty())
throw new IllegalArgumentException();
return new StringRequirementsImpl(parameter, name, new Configuration());
}
static class Configuration {
private Object context = ImmutableMap.of();
}
static class StringRequirementsImpl {
private String parameter;
private String name;
private Configuration config;
private ObjectRequirementsImpl asObject;
StringRequirementsImpl(String parameter, String name, Configuration config) {
this.parameter = parameter;
this.name = name;
this.config = config;
this.asObject = new ObjectRequirementsImpl(parameter, name, config);
}
}
static class ObjectRequirementsImpl {
private Object parameter;
private String name;
private Configuration config;
ObjectRequirementsImpl(Object parameter, String name, Configuration config) {
this.parameter = parameter;
this.name = name;
this.config = config;
}
}
}
Прежде всего, я проверил -XX:+PrintInlining
, что весь эталон встроен в один большой метод. Очевидно, что в этом компиляционном блоке много узлов, и для хранения всех промежуточных переменных недостаточно регистров процессора. То есть, компилятор должен spill некоторые из них.
- В
assertMethod
4 регистра просочились в стек перед вызовом trim()
.
- В
requireMethod
7 регистров просыпаются позже, после вызова new Configuration()
.
-XX:+PrintAssembly
вывод:
assertMethod | requireMethod
-------------------------|------------------------
mov %r11d,0x5c(%rsp) | mov %rcx,0x20(%rsp)
mov %r10d,0x58(%rsp) | mov %r11,0x48(%rsp)
mov %rbp,0x50(%rsp) | mov %r10,0x30(%rsp)
mov %rbx,0x48(%rsp) | mov %rbp,0x50(%rsp)
| mov %r9d,0x58(%rsp)
| mov %edi,0x5c(%rsp)
| mov %r8,0x60(%rsp)
Это почти единственное различие между двумя скомпилированными методами в дополнение к проверке if (enabled)
. Таким образом, разница в производительности объясняется большим количеством переменных, разлитых в память.
Почему меньший метод скомпилирован менее оптимальным? Хорошо, проблема распределения регистров, как известно, является NP-полной. Поскольку он не может быть решен идеально в разумные сроки, компиляторы обычно полагаются на определенные эвристики. В большом методе крошечная вещь, такая как дополнительный if
, может значительно изменить результат алгоритма распределения регистров.
Однако вам не нужно об этом беспокоиться. Эффект, который мы видели, не означает, что requireMethod
всегда скомпилирован хуже. В других случаях использование графа компиляции будет совершенно иным, поскольку вложение. Во всяком случае, разница в 1 наносекунде не является ничем для реальной производительности приложения.
Ответ 2
Вы запускаете свой тест в рамках одного процесса VM, задавая forks(1)
. Во время выполнения виртуальная машина просматривает ваш код и пытается выяснить, как он действительно выполняется. Затем он создает так называемые профили для оптимизации вашего приложения в соответствии с этим наблюдаемым поведением.
Что наиболее вероятно происходит здесь, называется загрязнением профиля, когда запуск первого эталона влияет на результат второго эталона. Слишком упрощенное: если ваша виртуальная машина была обучена делать (а) очень хорошо, запустив свой бенчмарк, потребуется дополнительное время, чтобы она привыкнуть к выполнению (б) после этого. Следовательно, (b), кажется, занимает больше времени.
Чтобы избежать этого, запустите свой тест с несколькими вилами, где различные тесты выполняются на свежих VM-процессах, чтобы избежать такой фильтрации профиля. Вы можете больше узнать о форкировании в образцах, которые предоставляются JMH.
Вы также должны проверить образец в состоянии; вы не должны ссылаться на свой ввод как константы, но пусть JMH обрабатывает значение escape, чтобы применить фактическое вычисление.
Я предполагаю, что - если применить их правильно - оба теста будут иметь сходное время выполнения.
Обновить. Вот что я получаю для фиксированного теста:
Benchmark Mode Cnt Score Error Units
MyBenchmark.assertMethod avgt 40 17,592 ± 1,493 ns/op
MyBenchmark.requireMethod avgt 40 17,999 ± 0,920 ns/op
Ради завершения, я также провел тест с перфекционизмом, и оба метода в основном скомпилированы в одно и то же.
Ответ 3
Отвечая на мой собственный вопрос:
Кажется, что наложение искажает результаты. Все, что мне нужно было сделать, чтобы получить последовательные, значимые результаты, было следующее:
- Блокировка часов процессора (минимальный/максимальный CPU установлен на 99% в Windows Power Options)
- Отключить inlining, аннотируя оба метода с помощью
@CompilerControl(CompilerControl.Mode.DONT_INLINE)
.
Теперь я получаю следующие результаты:
Benchmark Mode Cnt Score Error Units
MyBenchmark.assertMethod avgt 200 11.462 ± 0.048 ns/op
MyBenchmark.requireMethod avgt 200 11.138 ± 0.062 ns/op
Я попытался проанализировать вывод -XX:+UnlockDiagnosticVMOptions -XX:+PrintInlining
, но не смог найти ничего плохого. Оба метода, похоже, встраиваются одинаково. < & развести руками GT;
Исходный код исходного кода:
import java.util.concurrent.TimeUnit;
import static org.bitbucket.cowwoc.requirements.Requirements.assertThat;
import static org.bitbucket.cowwoc.requirements.Requirements.requireThat;
import org.bitbucket.cowwoc.requirements.StringRequirements;
import org.openjdk.jmh.annotations.Benchmark;
import org.openjdk.jmh.annotations.CompilerControl;
import org.openjdk.jmh.annotations.Mode;
import org.openjdk.jmh.annotations.Scope;
import org.openjdk.jmh.annotations.State;
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;
@State(Scope.Benchmark)
public class MyBenchmark {
private String name = "name";
private String value = "value";
@Benchmark
public void emptyMethod() {
}
// Inlining leads to unexpected results: https://stackoverflow.com/a/38860869/14731
@Benchmark
@CompilerControl(CompilerControl.Mode.DONT_INLINE)
public StringRequirements assertMethod() {
return assertThat(value, name).isNotNull().isNotEmpty();
}
@Benchmark
@CompilerControl(CompilerControl.Mode.DONT_INLINE)
public StringRequirements requireMethod() {
return requireThat(value, name).isNotNull().isNotEmpty();
}
public static void main(String[] args) throws RunnerException {
Options opt = new OptionsBuilder()
.include(MyBenchmark.class.getSimpleName())
.jvmArgsAppend("-ea")
.forks(3)
.timeUnit(TimeUnit.NANOSECONDS)
.mode(Mode.AverageTime)
.build();
new Runner(opt).run();
}
}
UPDATE: apangin, кажется, понял, почему assertMethod()
быстрее, чем requireMethod()
.
Ответ 4
Это очень часто встречается в микрообъектах. Когда я загружаю свой код, я получаю тот же результат, но с другими цифрами, по-видимому, мой компьютер медленнее вашего. Однако, если я изменю ваш источник, чтобы использовать 5 вилок, 100 итераций прогрева и 20 итераций измерений, то requireMethod будет немного быстрее, чем assertMethod, как ожидалось.
JMH замечательный, но очень легко писать тесты, которые выглядят хорошо, но там, где вы не можете доверять результатам, поскольку слишком много итераций.