Микробенчмаркинг с JMH: Мера, не думаю!

Я уверен, что вы все слышали, что присвоение переменной null помогает сборщику мусора или не объявляет final метода, улучшая выравнивание…. Но то, что вы также знаете, это то, что JVM эволюционировали кардинально, и то, что было правдой вчера, может не быть правдой сегодня . Итак, как мы узнаем, что наш код работает? Ну, мы не делаем, потому что мы не должны угадывать, что делает JVM … мы просто измеряем!

Мера, не угадай!

Как однажды сказал мой друг Кирк Пеппердин: « Мера, не угадай ». Мы все сталкивались с проблемами производительности в наших проектах, и нас попросили настроить случайные биты в нашем исходном коде … в надежде, что производительность улучшится. Вместо этого нам следует настроить среду стабильной производительности (операционную систему, JVM, сервер приложений, базу данных …), проводить непрерывные измерения, устанавливать некоторые цели производительности … затем предпринимать действия, когда наши цели не достигнуты. Непрерывная поставка, непрерывное тестирование — это одно, а непрерывное измерение — это еще один шаг.

В любом случае, производительность — это мрачное искусство, и это не цель этого поста. Нет, я просто хочу сосредоточиться на микробенчмаркинге и показать вам, как использовать JMH в реальном случае: ведение журнала .

Микробенчмаркинг

Я уверен, что, как и я, вы провели последние десятилетия, переходя от одной среды ведения журналов к другой, и вы видели разные способы записи журналов отладки:

logger.debug("Concatenating strings " + x + y + z);

logger.debug("Using variable arguments {} {} {}", x, y, z);

if (logger.isDebugEnabled())
  logger.debug("Using the if debug enabled {} {} {}", x, y, z);

Все это отладочные сообщения, и нам обычно все равно, потому что в производстве мы работаем с уровнем INFO или WARNING. Но журналы отладки могут повлиять на нашу производительность … даже если мы находимся на уровне ПРЕДУПРЕЖДЕНИЕ. Чтобы доказать это, мы можем использовать Java Microbenchmarking Harness (JMH), чтобы быстро создать микробенчмарки и измерить производительность трех механизмов ведения журнала: объединение строк, использование переменных аргументов и использование отладки if .

Настройка JMH

JMH — это инструмент Java для создания, запуска и анализа нано / микро / милли / макро тестов, написанных на Java и других языках, предназначенных для JVM. Его очень легко настроить, и благодаря архетипу Maven мы можем быстро получить скелет проекта JMH и приступить к работе. Для этого выполните следующую команду Maven:

$ mvn archetype:generate -DinteractiveMode=false -DarchetypeGroupId=org.openjdk.jmh \
      -DarchetypeArtifactId=jmh-java-benchmark-archetype -DarchetypeVersion=1.4.1 \
      -DgroupId=org.agoncal.sample.jmh -DartifactId=logging -Dversion=1.0

Этот архетип Maven создает следующую структуру проекта:

• Файл pom.xml с зависимостями JMH и настроенным плагином maven-shade-plugin для получения uber-jar
• Пустой класс MyBenchmark с аннотацией @Benchmark

На данный момент мы еще ничего не сделали, но проект микробенчмарка уже запущен и работает. Упаковка кода с Maven создаст uber-jar с именем benchmarks.jar.

$ mvn clean install
$ java -jar target/benchmarks.jar

Когда мы выполняем uber-jar, мы видим забавный вывод в консоли: JMH зацикливается, нагревает JVM, выполняет код внутри аннотированного метода @Benhmark (пока пустой метод) и дает нам количество операций в секунду

# Run progress: 30,00% complete, ETA 00:04:41
# Fork: 4 of 10
# Warmup Iteration   1: 2207650172,188 ops/s
# Warmup Iteration   2: 2171077515,143 ops/s
# Warmup Iteration   3: 2147266359,269 ops/s
# Warmup Iteration   4: 2193541731,837 ops/s
# Warmup Iteration   5: 2195724915,070 ops/s
# Warmup Iteration   6: 2191867717,675 ops/s
# Warmup Iteration   7: 2143952349,129 ops/s
# Warmup Iteration   8: 2187759638,895 ops/s
# Warmup Iteration   9: 2171283214,772 ops/s
# Warmup Iteration  10: 2194607294,634 ops/s
# Warmup Iteration  11: 2195047447,488 ops/s
# Warmup Iteration  12: 2191714465,557 ops/s
# Warmup Iteration  13: 2229074852,390 ops/s
# Warmup Iteration  14: 2221881356,361 ops/s
# Warmup Iteration  15: 2240789717,480 ops/s
# Warmup Iteration  16: 2236822727,970 ops/s
# Warmup Iteration  17: 2228958137,977 ops/s
# Warmup Iteration  18: 2242267603,165 ops/s
# Warmup Iteration  19: 2216594798,060 ops/s
# Warmup Iteration  20: 2243117972,224 ops/s
Iteration   1: 2201097704,736 ops/s
Iteration   2: 2224068972,437 ops/s
Iteration   3: 2243832903,895 ops/s
Iteration   4: 2246595941,792 ops/s
Iteration   5: 2241703372,299 ops/s
Iteration   6: 2243852186,017 ops/s
Iteration   7: 2221541382,551 ops/s
Iteration   8: 2196835756,509 ops/s
Iteration   9: 2205740069,844 ops/s
Iteration  10: 2207837588,402 ops/s
Iteration  11: 2192906907,559 ops/s
Iteration  12: 2239234959,368 ops/s
Iteration  13: 2198998566,646 ops/s
Iteration  14: 2201966804,597 ops/s
Iteration  15: 2215531292,317 ops/s
Iteration  16: 2155095714,297 ops/s
Iteration  17: 2146037784,423 ops/s
Iteration  18: 2139622262,798 ops/s
Iteration  19: 2213499245,208 ops/s
Iteration  20: 2191108429,343 ops/s

Добавление SLF4j в тест

Помните, что сценарий использования — это ведение журнала в микробенчах. В созданном проекте я использую SFL4J с Logback. Поэтому мне нужно добавить эти зависимости в pom.xml:

<dependency>
  <groupId>org.slf4j</groupId>
  <artifactId>slf4j-api</artifactId>
  <version>1.7.7</version>
</dependency>
<dependency>
  <groupId>ch.qos.logback</groupId>
  <artifactId>logback-classic</artifactId>
  <version>1.0.11</version>
</dependency>

Затем я добавляю файл logback.xml, который выводит только журналы INFO (поэтому я уверен, что трассировки уровня отладки не регистрируются):

<configuration>
  <appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
    <encoder>
      <pattern>%highlight(%d{HH:mm:ss.SSS} [%thread] %-5level %logger - %msg%n)</pattern>
    </encoder>
  </appender>

  <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
    <encoder><pattern>%msg%n</pattern></encoder>
  </appender>

  <root level="INFO">
    <appender-ref ref="CONSOLE" />
  </root>
</configuration>

Хорошая вещь с плагином maven-shade-plugin заключается в том, что когда я упаковываю приложение, все зависимости, файлы конфигурации и т. Д. Все сливаются в uber-jar target / benchmarks.jar.

Использование конкатенации строк в журналах

Давайте сделаем первый микро-тест: использование логов с конкатенацией строк. Идея состоит в том, чтобы взять класс MyBenchmark и добавить необходимый код в метод, аннотированный @Benchmark, и позволить JMH сделать все остальное. Итак, мы добавляем Logger, создаем несколько строк (x, y, z), делаем цикл и регистрируем отладочное сообщение с конкатенацией строк. Это будет выглядеть так:

import org.openjdk.jmh.annotations.Benchmark;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

public class MyBenchmark {

  private static final Logger logger = LoggerFactory.getLogger(MyBenchmark.class);

  @Benchmark
  public void testConcatenatingStrings() {

    String x = "", y = "", z = "";

    for (int i = 0; i < 100; i++) {
      x += i; y += i; z += i;

      logger.debug("Concatenating strings " + x + y + z);
    }
  }
}

Чтобы выполнить этот микро-тест, мы делаем как обычно, и мы увидим результаты итерации:

$ mvn clean install
$ java -jar target/benchmarks.jar

Использование переменных аргументов в журналах

Вторым микропроцессором является использование переменных переменных в журналах вместо объединения строк. Просто измените код, перепакуйте и выполните его.

  @Benchmark
  public void testVariableArguments() {

    String x = "", y = "", z = "";

    for (int i = 0; i < 100; i++) {
      x += i; y += i; z += i;

      logger.debug("Variable arguments {} {} {}", x, y, z);
    }
  }

Использование оператора If в журналах

Наконец, что не менее важно, старый добрый isDebugEnabled () в журналах, который «должен оптимизировать вещи».

  @Benchmark
  public void testIfDebugEnabled() {

    String x = "", y = "", z = "";

    for (int i = 0; i < 100; i++) {
      x += i; y += i; z += i;

      if (logger.isDebugEnabled())
        logger.debug("If debug enabled {} {} {}", x, y, z);
    }
  }

Результат микробенчмарков

После выполнения трех микробенчмарков мы получаем то, что ожидали (помните, не угадывайте, измеряйте). Чем больше операций в секунду, тем лучше. Поэтому, если мы посмотрим на последнюю строку следующей таблицы, мы заметим, что лучшая производительность — это isDebugEnabled, а хуже — конкатенация строк. Тогда, как мы видим, переменный аргумент без isDebugEnabled также неплох, плюс мы получаем наглядность (меньше кода котельной пластины). Так что я пойду с переменными аргументами!

Вывод

В последние десятилетия JVM развивались кардинально . Шаблон проектирования, который оптимизировал бы наш код десять лет назад, больше не является точным. Единственный способ убедиться, что один кусок кода лучше другого, — это измерить его. JMH — это идеальный инструмент для простого и быстрого микроконтроля фрагментов кода или, как в этом посте, внешней среды (ведение журналов, служебные классы, манипуляции с датами, Apache Commons….). Конечно, рассуждение о небольшом разделе кода — это только один шаг, потому что нам обычно нужно анализировать общую производительность приложения. Благодаря JMH этот первый шаг легко сделать.

И не забудьте проверить примеры JMH , там полно интересных идей.

Рекомендации

• Образцы JMH
• Руководство по настройке производительности Java
• Использование JMH для Java Microbenchmarking
• Написание тестов Java Micro с помощью JMH: Juicy