Usetech 5 авг 2022 в 07:17

Пишем тесты производительности под Webflux

8 мин

Блог компании UsetechJava*

Туториал

Cезон Java

Александр Леонов

Руководитель группы разработки

Добрый день! Меня зовут Александр Леонов, я руководитель группы разработки одной из распределённых команд Usetech. Сегодня я хочу рассказать вам о том, как написать карманный тест производительности на неблокирующий код Webflux. Статья рассчитана на разработчиков, которые разрабатывают API или выполняют оптимизационный рефакторинг медленного кода. Итак, начнём.

Дисклеймер

Весь приведённый ниже код является тестовым, но отражает основные моменты реального кода.

Данный материал направлен на написание бенчмарков, покрывающих изнутри отдельные части кода приложения. Для тонкой настройки производительности приложения целиком необходимы люди соответствующих компетенций!

Введение

В обычный рабочий день, в лс стучится менеджер с просьбой откинуть все текущие дела и переключиться на приоритетную задачу, суть которой сводится к следующему:

Есть корпоративный портал, состоящий из мобильного приложения, фронта и бэкенда API. У последнего есть эндпоинт, предоставляющий всю информацию по профилю сотрудника, которую он собирает с внутренней БД и сервисов. Со временем логика этого эндпоинта разрасталась и стала тормозить, что поначалу вызывало дискомфорт, а потом и всеобщую панику, когда вместо «плохих» 5 секунд ожидания фронт начал проседать до «невозможных» 22-24 секунд. Кэшированием проблему не решить, т.к. есть некие данные, которые постоянно меняются и должны быть актуальны при каждом запросе к API. Нужно срочно это исправить и подготовить отчёт с цифрами до оптимизации и после.

Задача ясна, давайте исправлять ситуацию.

Взглянув на код бэкенда и пройдя от контроллера, мы наблюдаем вызов метода:

public interface UserService {	
	Mono<User> profileInfo(UUID userId);
   // ...
}

Дисклеймер

В статье не использовалась реализация реального сервиса, вместо неё были использованы заглушки:

@Service
public class UserServiceImpl implements UserService {
	
	// ...
	
	@Override
	public Mono<User> profileInfo(UUID userId) {
    	final var user = User.builder().build();
    	return Mono.just(user).delayElement(Duration.ofMillis(12000));
	}
 
	@Override
	public Mono<User> userInfo(UUID userId) {
    	final var user = User.builder().build();
    	return Mono.just(user).delayElement(Duration.ofMillis(5010));
	}
 
   // ...
}

Тут приходит понимание, что это Webflux, а значит придётся писать неблокирующие тесты.

Также, первое, что приходит в голову, если у нас обычный метод с запросом в базу — выполнить план запроса при прогоне sql запроса. В данном же случае, этого недостаточно, потому что фича тянет данные из разных источников — БД, внешние сервисы… Ещё у нас есть логика обработки результатов в коде.

По ходу исследования кодовой базы, обнаруживаем, что простейшие неблокирующие тесты под наш код имеются:

	@Test
	public void profileInfo() {
    	StepVerifier.create(userService.profileInfo(USER_ID)
                        .log("profile-info", Level.INFO, SignalType.ON_NEXT)
            	)
                .expectNextCount(1)
                .verifyComplete();
	}

Это хорошо, т.к. вся логика моков вызовов внутренних сервисов уже написана и нам необходимо будет только заменить возвращаемые данные от сервисов на данные, с которыми система тормозит. Благо, ребята из QA предоставили curl как воспроизвести дефект.

Теперь надо зафиксировать текущий плохой результат на цифрах, но возникает вопрос, как лучше это сделать. В идеале, не просто разово решить проблему и нивелировать её в будущем, но и дать команде данного бэкенд сервиса инструмент, с помощью которого они смогут производить оценку производительности кода сразу, после его написания.

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

@Test
public void profileInfo_naivePerfomanceTest() {
	long startTime = System.currentTimeMillis();
	StepVerifier.create(userService.profileInfo(USER_ID)
                    .map(result -> {
                    	long finishTime = System.currentTimeMillis();
 
                    	System.out.printf("Start %d \nEnd %d%n", startTime, finishTime);
                        return result;
                	})
                	.log("profile-info", Level.INFO, SignalType.ON_NEXT)
        	)
            .expectNextCount(1)
            .verifyComplete();
}

Но что, если у нас уже приложение прогрето и на холодном старте будут опять тормоза? К тому же существует потребность прогона логики несколько раз, вычисления среднего арифметического и т.д. В таком случае нам помогут бенчмарки/перфоманс тесты/тесты производительности.

Если рассматривать классические варианты написания перфоманс тестов на Java, то сразу на ум приходит JMH. В формате данной статьи остановимся на нём, как первичном решении из JDK, но можете написать в комментариях, какие инструменты или фреймворки используете для написания тестов производительности.

Но как им тестировать реактивный код? Неужели нет никакой стандартной либы для тестирования Webflux? Есть reactor-test зависимость, с помощью которой можно нормально писать неблокирующие тесты. Может, существует такой же инструмент для написания перфоманс тестов неблокирующего кода?

На момент решения проблемы, поиски инструмента «из коробки» не увенчались успехом. Тогда зародилась идея скрестить reactor-test и JMH. Но сначала поправим код медленного метода сервиса.

Для начала создадим новый метод, в котором будут оптимизации, чтобы на случай отката не было больно.

public interface UserService {
	@Deprecated
	/**
 	* Use UserService.userInfo
 	*/
	Mono<User> profileInfo(UUID userId);
	Mono<User> userInfo(UUID userId);
}

После проведения рефакторинга кода в новом методе и первичных прогонах через API локально, ситуация на первый взгляд исправлена. Осталось получить результат в цифрах, как было до и после.

После пары часов исследований и практики скрещивания аннотаций JMH и Spring, на основе имеющегося юнит теста, был реализован отдельный тест производительности, подобный текущему (убраны моки и лишний код, изменены параметры настроек):

package ru.usetech.portal.service.benchmark;
import org.junit.jupiter.api.Test;
import org.openjdk.jmh.annotations.*;
import org.openjdk.jmh.results.format.ResultFormatType;
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;
import org.openjdk.jmh.runner.options.TimeValue;
import org.springframework.beans.factory.annotation.Autowired;
import org.springframework.boot.test.context.SpringBootTest;
import org.springframework.context.annotation.Profile;
import reactor.test.StepVerifier;
import ru.usetech.portal.service.UserService;
import ru.usetech.portal.service.impl.UserServiceImpl;
import java.util.UUID;
import java.util.concurrent.TimeUnit;
@Profile("local")
@State(Scope.Benchmark)
@BenchmarkMode(Mode.AverageTime)
@OutputTimeUnit(TimeUnit.MILLISECONDS)
@SpringBootTest(classes = {
    	UserServiceImpl.class
})
public class UserServicePerformanceTest {
	private static final UUID USER_ID = UUID.randomUUID();
	// JMH isn't support autowired services
	private static UserService userService;
	// The @State annotation can only be applied to the classes having the default public constructor.
	@Autowired
	public void injectService(UserService userService) {
        UserServicePerformanceTest.userService = userService;
	}
 
	@Test
	public void start() throws RunnerException {
    	Options opts = new OptionsBuilder()
            	.warmupIterations(3)
            	.warmupTime(TimeValue.seconds(20))
            	.measurementIterations(3)
           	 .measurementTime(TimeValue.seconds(20))
            	.forks(0) // use only for debug.
            	.threads(1)
                .shouldDoGC(true)
                .shouldFailOnError(true)
                .resultFormat(ResultFormatType.JSON)
            	.build();
    	new Runner(opts).run();
	}
	@Benchmark
	public void profileInfo() {
    	StepVerifier.create(userService.profileInfo(USER_ID))
                .expectNextCount(1)
                .verifyComplete();
	}
	@Benchmark
	public void profileInfoNew() {
    	StepVerifier.create(userService.userInfo(USER_ID))
                .expectNextCount(1)
                .verifyComplete();
	}
}

В этой реализации есть несколько нюансов, отмеченных в комментариях, связанных с особенностями работы JMH, всё-таки не стоит забывать, что мы пытались внедрить его к инструментам обычного юнит тестирования. Более того, в текущей реализации можно писать бенчмарки и под блокирующий код, внутри методов, помеченных @Benchmark. Единственное, было убрано логирование, чтобы не спамить вывод консоли.

Давайте запустим этот тест и посмотрим как выглядит результат работы:

Результат работы

WARNING: An illegal reflective access operation has occurred
WARNING: Illegal reflective access by org.openjdk.jmh.util.Utils (file:/home/alexandr/.m2/repository/org/openjdk/jmh/jmh-core/1.22/jmh-core-1.22.jar) to field java.io.PrintStream.charOut
WARNING: Please consider reporting this to the maintainers of org.openjdk.jmh.util.Utils
WARNING: Use --illegal-access=warn to enable warnings of further illegal reflective access operations
WARNING: All illegal access operations will be denied in a future release
# JMH version: 1.22
# VM version: JDK 11.0.16, OpenJDK 64-Bit Server VM, 11.0.16+8-LTS
# VM invoker: /usr/lib/jvm/zulu-11/bin/java
# VM options: -ea -Didea.test.cyclic.buffer.size=1048576 -javaagent:/usr/share/idea/lib/idea_rt.jar=38117:/usr/share/idea/bin -Dfile.encoding=UTF-8
# Warmup: 3 iterations, 20 s each
# Measurement: 3 iterations, 20 s each
# Timeout: 10 min per iteration
# Threads: 1 thread, will synchronize iterations
# Benchmark mode: Average time, time/op
# Benchmark: ru.usetech.portal.service.benchmark.UserServicePerformanceTest.profileInfo
 
# Run progress: 0,00% complete, ETA 00:04:00
# Fork: N/A, test runs in the host VM
# *** WARNING: Non-forked runs may silently omit JVM options, mess up profilers, disable compiler hints, etc. ***
# *** WARNING: Use non-forked runs only for debugging purposes, not for actual performance runs. ***
# Warmup Iteration   1: 12042,567 ms/op
# Warmup Iteration   2: 12000,521 ms/op
# Warmup Iteration   3: 12000,538 ms/op
Iteration   1: 12000,406 ms/op
Iteration   2: 12000,493 ms/op
Iteration   3: 12000,438 ms/op
 
Result "ru.usetech.portal.service.benchmark.UserServicePerformanceTest.profileInfo":
12000,446 ±(99.9%) 0,810 ms/op [Average]
(min, avg, max) = (12000,406, 12000,446, 12000,493), stdev = 0,044
CI (99.9%): [11999,635, 12001,256] (assumes normal distribution)
 
# JMH version: 1.22
# VM version: JDK 11.0.16, OpenJDK 64-Bit Server VM, 11.0.16+8-LTS
# VM invoker: /usr/lib/jvm/zulu-11/bin/java
# VM options: -ea -Didea.test.cyclic.buffer.size=1048576 -javaagent:/usr/share/idea/lib/idea_rt.jar=38117:/usr/share/idea/bin -Dfile.encoding=UTF-8
# Warmup: 3 iterations, 20 s each
# Measurement: 3 iterations, 20 s each
# Timeout: 10 min per iteration
# Threads: 1 thread, will synchronize iterations
# Benchmark mode: Average time, time/op
# Benchmark: ru.usetech.portal.service.benchmark.UserServicePerformanceTest.profileInfoNew
 
# Run progress: 50,00% complete, ETA 00:02:28
# Fork: N/A, test runs in the host VM
# *** WARNING: Non-forked runs may silently omit JVM options, mess up profilers, disable compiler hints, etc. ***
# *** WARNING: Use non-forked runs only for debugging purposes, not for actual performance runs. ***
# Warmup Iteration   1: 5010,497 ms/op
# Warmup Iteration   2: 5010,426 ms/op
# Warmup Iteration   3: 5010,453 ms/op
Iteration   1: 5010,429 ms/op
Iteration   2: 5010,463 ms/op
Iteration   3: 5010,420 ms/op
 
Result "ru.usetech.portal.service.benchmark.UserServicePerformanceTest.profileInfoNew":
5010,438 ±(99.9%) 0,408 ms/op [Average]
(min, avg, max) = (5010,420, 5010,438, 5010,463), stdev = 0,022
CI (99.9%): [5010,030, 5010,845] (assumes normal distribution) 
# Run complete. Total time: 00:04:32
REMEMBER: The numbers below are just data. To gain reusable insights, you need to follow up on
why the numbers are the way they are. Use profilers (see -prof, -lprof), design factorial
experiments, perform baseline and negative tests that provide experimental control, make sure
the benchmarking environment is safe on JVM/OS/HW level, ask for reviews from the domain experts.
Do not assume the numbers tell you what you want them to tell.
 
Benchmark                              	Mode  Cnt      Score   Error  Units
UserServicePerformanceTest.profileInfo 	avgt    3  12000,446 ± 0,810  ms/op
UserServicePerformanceTest.profileInfoNew  avgt    3   5010,438 ± 0,408  ms/op
Benchmark result is saved to jmh-result.json

Здесь нас интересует только конечный вывод:

Benchmark                              	Mode  Cnt      Score   Error  Units
UserServicePerformanceTest.profileInfo 	avgt    3  12000,446 ± 0,810  ms/op
UserServicePerformanceTest.profileInfoNew  avgt    3   5010,438 ± 0,408  ms/op
Benchmark result is saved to jmh-result.json

Более того, выгрузился отчёт в отдельный файл в формате JSON.

Таким образом, задача оптимизации решена и доказана на цифрах, а у команды разработчиков появился код, который можно переиспользовать и затем улучшить при разборе задач на оптимизацию критичных частей API.

Если вы не согласны с применённым подходом или для Webflux наконец-то появилось решение «из коробки», буду рад вашим комментариям — с удовольствием наверстаю упущенное.

Благодарю за время, уделённое прочтению статьи и надеюсь, что она была полезной.

Теги:

Хабы:

Пишем тесты производительности под Webflux

Александр Леонов

Введение

Публикации

Информация

Истории