Привет, сегодня будет объёмная и обстоятельная статья о низкоуровневом профилировании и диагностике производительности. Многократно в комментариях к докладам и статьям пользователи высказывали пожелание увидеть не просто перечисление шаблонов "как нужно" и "как не нужно", а целостную историю. Поэтому вот вам статья про конкретный кейс и его историю :). Не удивляйтесь, что начнём мы с JPA, хотя казалось бы где оно и где ассемблер. По ходу дела вы всё поймёте.
Часть материала, лёгшего в основу этого доклада ранее размещалась мной здесь, поэтому если вдруг вам покажется, что где-то вы уже читали это, то чутьё вас не подвело :). И всё же эта статья не является плагиатом, а скорее более полной и развёрнутой историей, объясняющей что, как, почему и зачем. Исходный код доступен тут.
История
Однажды нам поставили задачу разработать новый функционал для нашего довольно большого и древнего как помёт мамонта долгоживущего приложения, использовавшего для работы с данными обычный энтерпрайз-набор: СУБД Oracle, Hibernate, Spring Data JPA. Особенностью нашего приложения было наличие нескольких жирненьких сущностей (с десятками полей), при чём часто нам были нужны буквально считанные из них. Проблему извлечения нескольких полей из многих (минуя загрузку всей сущности и уменьшая трафик) мы решали с помощью DTO:
// жирная сущность
@Entity
public class ManyFieldsEntity {
@Id
private Long id;
@Column
private String extId;
@Column
private String name;
@Column
private BigDecimal amount1;
@Column
private BigDecimal amount2;
@Column
private BigDecimal amount3;
@Column
private BigDecimal amount4;
@Column
private BigDecimal amount5;
@Column
private BigDecimal amount6;
@Column
private BigDecimal amount7;
@Column
private BigDecimal amount8;
}
// DTO
@Getter
@RequiredArgsConstructor
public class HasIdAndNameDto {
private final Long id;
private final String name;
}
// метод для извлечения данных
public interface ManyFieldsRepository extends JpaRepository<ManyFieldsEntity, Long> {
@Query("select new com.tsypanov.domain.HasIdAndNameDto(e.id, e.name)" +
" from ManyFieldsEntity e " +
" where e.name = :name")
Collection<HasIdAndNameDto> findAllByNameUsingDto(String name);
}Уверен, большинство из вас хоть раз писало что-то подобное. В нашем случае один из разработчиков предложил альтернативу — проекции.
Что это такое и с чем их едят?
Проекция — это представление части сущности с помощью интерфейса с геттерами, соответствующими именам полей:
public interface HasIdAndName {
Long getId();
String getName();
}Этот подход имеет ряд преимуществ перед привычными DTO:
интерфейсы сами по себе более гибкий инструмент, чем класс. Реализовав интерфейс в указанной выше сущности и DTO можно написать сервисный метод, одинаково работающий и с сущностью, и с проекцией, и с DTO
для объявления метода внутри репозитория более не требуется явное объявление конструктора, что сильно всё упрощает (особенно когда в конструкторе DTO не 1-2 аргумента, а 10), а также позволяет вообще отказаться от
@Queryв пользу правильно именованного метода (Спринг создаст запрос самостоятельно). Таким образом, код можно записать лаконичнее:
public interface ManyFieldsRepository extends JpaRepository<ManyFieldsEntity, Long> {
Collection<HasIdAndName> findAllByName(String name);
}-
"Идея" поддерживает проекции и даёт подсказки при написании репозиторных методов, снижая вероятность написания кривого запроса, который упадёт только при обращении к нему. К тому же при рефакторинге интерфейса сам репозиторный метод не будет затронут (в старых версиях "Идеи" переименование/добавление/удаление полей в DTO не затрагивало их использование в JPQL-запросах, не всегда работала подсветка при неправильном порядке аргументов в конструкторе и т. п.)
И мы решили попробовать реализовать новый функционал с помощью проекций.
Ложка дёгтя
Вероятно, вы уже догадались, что в огромной бочке мёда оказалась ложка дёгтя плохой производительности. Сравним время отклика при выгрузке 1 и 100 DTO/проекций с помощью простого бенчмарка:
@State(Scope.Thread)
@OutputTimeUnit(TimeUnit.MICROSECONDS)
@BenchmarkMode(value = Mode.AverageTime)
public class ProjectionVsDtoBenchmark {
private ManyFieldsRepository repository;
@Param({"1", "100"})
private int count;
@Setup
public void init() {
ConfigurableApplicationContext context = SpringApplication.run(Application.class);
context.registerShutdownHook();
repository = context.getBean(ManyFieldsRepository.class);
List<ManyFieldsEntity> entities = ThreadLocalRandom.current()
.longs(count)
.boxed()
.map(randomLong -> new ManyFieldsEntity(randomLong, String.valueOf(randomLong), "ivan"))
.collect(Collectors.toList());
repository.saveAll(entities);
}
//DTO реализует HasIdAndName, поэтому возвращаемый тип тот же
@Benchmark
public Collection<HasIdAndName> dto() {
return repository.findAllByNameUsingDto("ivan");
}
@Benchmark
public Collection<HasIdAndName> projection() {
return repository.findAllByName("ivan");
}
}Может показаться, что раз мы обращаемся к базе (пусть даже это и H2 на нашем хосте), то львиная доля времени тратится именно на запрос и передачу данных, следовательно цифры будут примерно одинаковыми.
Однако:
Benchmark (count) Score Error Units
dto 1 11,409 ± 0,741 us/op
projection 1 12,886 ± 0,194 us/op
dto 100 40,326 ± 0,738 us/op
projection 100 220,189 ± 5,668 us/op
dto:·gc.alloc.rate.norm 1 13994,528 ± 22,042 B/op
projection:·gc.alloc.rate.norm 1 21224,235 ± 19,369 B/op
dto:·gc.alloc.rate.norm 100 33313,019 ± 22,609 B/op
projection:·gc.alloc.rate.norm 100 517354,738 ± 34,719 B/opИтог прогона несколько обескураживает: если получение одного объекта стоит более-менее одинаково, то при получении 100 объектов возвращающий проекцию метод ManyFieldsRepository.findAllByNameUsingDto() начинает сильно проигрывать. Это контринтуитивно, ведь чаще всего на скорость отклика влияет именно запрос. Что ж, нужно расчехлять профилировщик и искать узкие места.
VisualVM ввиду его "попсовости" и некоторых врождённых пороков рассматривать не будем, начнём с JFR, благо его можно подключить напрямую из бенчмарка (вообще запуск из главного метода - это не очень "православный" подход, правильнее всё-таки пускать бенчмарк из командной строки, но в данном случае это не столь важно):
public class BenchmarkRunner {
public static void main(String[] args) throws Exception {
Options opt = new OptionsBuilder()
.include(ProjectionProfilingBenchmark.class.getSimpleName())
.warmupIterations(10)
.warmupTime(TimeValue.seconds(1))
.measurementIterations(2) // два длинных прогона
.measurementTime(TimeValue.seconds(15))
.addProfiler(JavaFlightRecorderProfiler.class)
.forks(1) // 1 процесс для стабилизации скомпилированного кода
.shouldFailOnError(true)
.jvmArgsAppend( // допнастройки для правильной работы
"-XX:+UnlockDiagnosticVMOptions",
"-XX:+DebugNonSafepoints"
)
.build();
new Runner(opt).run();
}
}Обратите внимание, опыт ставится на "восьмёрке" (это важно, далее вы поймёте почему). Прогон завершён, посмотрим на числа (нажмите на изображение для полноразмерного просмотра):
Здесь ключевым является то, что лишь около 6% занимает исполнение запроса, а обработка полученных данных - без малого 80%. Разумеется, при использовании "боевой" БД на удалённом хосте соотношение сместится в сторону исполнения запроса.
Развернув метод ResultProcessor.processResult() видим следующее:
77% занимает создание проекции
35% занимает конструктор
ConcurrentReferenceHashMap25% занимает
ProxyFactory.getProxy()
Прокачивание ProxyFactory.getProxy() описано здесь, там всё слишком просто и неинтересно. Лучше посмотрим на ConcurrentReferenceHashMap: горячими методами являются конструктор, метод calculateShift() и конструктор вложенного класса CRHM$Segment (здесь и далее исходный код CRHM относится к версии Спринга 5.1.3). Вот они:
public ConcurrentReferenceHashMap(
int initialCapacity, float loadFactor, int concurrencyLevel, ReferenceType referenceType) {
Assert.isTrue(initialCapacity >= 0, "Initial capacity must not be negative");
Assert.isTrue(loadFactor > 0f, "Load factor must be positive");
Assert.isTrue(concurrencyLevel > 0, "Concurrency level must be positive");
Assert.notNull(referenceType, "Reference type must not be null");
this.loadFactor = loadFactor;
this.shift = calculateShift(concurrencyLevel, MAXIMUM_CONCURRENCY_LEVEL);
int size = 1 << this.shift;
this.referenceType = referenceType;
int roundedUpSegmentCapacity = (int) ((initialCapacity + size - 1L) / size);
this.segments = (Segment[]) Array.newInstance(Segment.class, size);
for (int i = 0; i < this.segments.length; i++) {
this.segments[i] = new Segment(roundedUpSegmentCapacity);
}
}
public Segment(int initialCapacity) {
this.referenceManager = createReferenceManager();
this.initialSize = 1 << calculateShift(initialCapacity, MAXIMUM_SEGMENT_SIZE);
this.references = createReferenceArray(this.initialSize);
this.resizeThreshold = (int) (this.references.length * getLoadFactor());
}
protected static int calculateShift(int minimumValue, int maximumValue) {
int shift = 0;
int value = 1;
while (value < minimumValue && value < maximumValue) {
value <<= 1;
shift++;
}
return shift;
}Первое, что вызывает сомнения в достоверности данных цифр - это доля calculateShift(). Сомнительно, что такой простой вычисляющий метод действительно занимает почти 17%.
Нужна повышенная точность, а значит на помощь идёт async-profiler. Упростим бенчмарк, чтобы профилировать только создание CRHM:
@OutputTimeUnit(TimeUnit.NANOSECONDS)
@BenchmarkMode(value = Mode.AverageTime)
public class CRHMBenchmark {
@Benchmark
public Object instantiate() {
return new ConcurrentReferenceHashMap<>();
}
}Добавим его в настройки нашего бенчмарка и подключим AsyncProfiler:
public class BenchmarkRunner {
public static void main(String[] args) throws Exception {
Options opt = new OptionsBuilder()
.include(CRHMBenchmark.class.getSimpleName())
.warmupIterations(10)
.warmupTime(TimeValue.seconds(1))
.measurementIterations(10)
.measurementTime(TimeValue.seconds(1))
.addProfiler(AsyncProfiler.class)
.forks(1)
.shouldFailOnError(true)
.build();
new Runner(opt).run();
}
}Обратите внимание, в этом случае нам уже не нужно указывать дополнительный настройки ВМ, они добавляются автоматически в методе AsyncProfiler.addJVMOptions(). Смотрим вывод:
ns percent samples top
---------- ------- ------- ---
4270110916 27.81% 427 o.s.u.ConcurrentReferenceHashMap$Segment.<init>
3920827445 25.53% 392 o.s.u.ConcurrentReferenceHashMap$ReferenceManager.<init>
3691037002 24.04% 369 o.s.u.ConcurrentReferenceHashMap.createReferenceManager
1719959854 11.20% 172 o.s.u.ConcurrentReferenceHashMap.<init>
439959922 2.87% 44 java.lang.ref.ReferenceQueue.<init>
279927288 1.82% 28 java.util.concurrent.locks.ReentrantLock.<init>
70590822 0.46% 7 smp_call_function_single_[k]Из профиля ожидаемо пропал calculateShift(), правда, ясности от этого не прибавилось. Вычитка кода позволяет выявить одно возможное улучшение: поскольку аргумент конструктора Segment(int) всегда один и тот же для всего цикла в конструкторе CRHM, то выражение 1 << calculateShift(initialCapacity, MAXIMUM_SEGMENT_SIZE) можно вычислить один раз. Существенного прироста это не даст.
Итак, мы в тупике: исходный код горячих методов небольшой, и "на глаз" ключ к пониманию проблемы не найти. JFR и async-profiler указали лишь примерное направление поиска, а для определения конкретной строчки понадобится более точный и низкоуровневый инструмент.
Вскрываем
Подключаем o.o.j.p.LinuxPerfAsmProfiler, для наглядности я вновь делаю это в коде (доступен вариант с аргументом командной строки -prof perfasm):
public class BenchmarkRunner {
public static void main(String[] args) throws Exception {
Options opt = new OptionsBuilder()
.include(CRHMBenchmark.class.getSimpleName())
.warmupIterations(10)
.warmupTime(TimeValue.seconds(1))
.measurementIterations(1) // одного длинного прогона достаточно
.measurementTime(TimeValue.seconds(10))
.addProfiler(LinuxPerfAsmProfiler.class)
.forks(1) // важно!
.shouldFailOnError(true)
.jvmArgsAppend(
"-XX:+UnlockDiagnosticVMOptions",
"-XX:+PrintAssembly"
)
.build();
new Runner(opt).run();
}
}Обратите внимание: использование этого профилировщика требует подготовительной работы, которую я описал в одной из предыдущих статей.
Также наличие 1 процесса здесь является решающим, ведь у разных процессов адреса команд с большой вероятностью будут разными, это отдельного оговорено в документации.
Изучаем собранные данные
На первый взгляд, там чёрт ногу сломит: непонятно где и что искать. Но если присмотреться, то слева мы видим долю времени, которую занимает та или иная инструкция, правее — её адрес, имя и соответствующий ей байт-код, а ещё правее — точное указание на метод и строку в исходном Java-коде! Обратите внимание: одному байт-коду может соответствовать несколько инструкций. Дальше дело техники: листаем код и ищем горячее место, например вот это:
// строка 78
4.82% 0x00007f137d227722: mov 0x8(%rsp),%r14Читатель сейчас чешет затылок и думает "М-м-м, и что я должен тут увидеть?" Признаюсь, я сам долго смотрел на это без единой внятной мысли, пока @apangin не подсказал, что перф часто смещает горячие места в выводе, это неприятное явление называется performance event skid и определено так:
The skid is defined as the distance between the IP(s) that caused the issue to the IP(s) where the event is tagged
Почитать об этом подробнее можно в статье Дениса Бахвалова.
Для нас это означает необходимость поискать где-то вокруг горячих строк:
0.44% 0x00007f137d22771b: mov %r10,%r13 ;*getfield segments
; - o.s.u.CRHM::<init>@121 (line 183)
0x00007f137d22771e: mov (%rsp),%r9d
4.82% 0x00007f137d227722: mov 0x8(%rsp),%r14
0.11% 0x00007f137d227727: mov 0x10(%rsp),%rsi
0x00007f137d22772c: mov 0x18(%rsp),%r11
0x00007f137d227731: mov 0x20(%rsp),%r8
0.66% 0x00007f137d227736: mov 0x30(%rsp),%rdi ;*aload_0
; - o.s.u.CRHM::<init>@128 (line 184)Байт-код getfield означает чтение поля, в данном случае segments, в строке 183:
for (int i = 0; i < this.segments.length; i++) {
this.segments[i] = new Segment(roundedUpSegmentCapacity);
}Почему так много и почему исполнение не оптимизировало доступ в таком простом коде? Чтобы ответить на этот вопрос нужно поискать другие горячие инструкции:
// строка 124
18.29% 0x00007f137d2277e4: mov 0x60(%r15),%rdxЗдесь понятно не больше, чем в первом примере, смотрим вокруг:
0.99% 0x00007f137d2277d7: mov %r12l,(%r10,%rcx)
0x00007f137d2277db: mov %r12d,0x14(%rbx)
0x00007f137d2277df: lock addl $0x0,(%rsp) ;*putfield count
; - o.s.u.CRHM$Segment::<init>@11 (line 476)
; - o.s.u.CRHM::<init>@141 (line 184)
18.29% 0x00007f137d2277e4: mov 0x60(%r15),%rdx
0x00007f137d2277e8: mov %rdx,%r10
0x00007f137d2277eb: add $0x18,%r10
0.55% 0x00007f137d2277ef: cmp 0x70(%r15),%r10Любопытно, целых 18,29% занимает запись в поле count в строке 476:
protected final class Segment extends ReentrantLock {
private volatile int count = 0;
}Похоже, это выстрел в десятку! Мы записываем 0 в поле целочисленного типа, которое просто по спецификации будет равно 0 (и всё это в цикле). А те самые 18,29% накручивает гадкий volatile:
@OutputTimeUnit(TimeUnit.NANOSECONDS)
@BenchmarkMode(value = Mode.AverageTime)
public class VolatileFieldZeroingBenchmark {
@Benchmark
public Object explicitInit() {
return new Class1();
}
@Benchmark
public Object defaultInit() {
return new Class2();
}
private static class Class1 {
private volatile boolean field = false;
}
private static class Class2 {
private volatile boolean field;
}
}В обоих случаях после создания объекта значение полей будет false, однако при явном присваивании стоимость существенно выше:
Benchmark Score Error Units
VolatileFieldZeroingBenchmark.explicitInit 11.200 ± 0.270 ns/op
VolatileFieldZeroingBenchmark.defultInit 3.447 ± 0.208 ns/opЗапись в волатильное поле заставляет компилятор вставлять инструкции для обеспечения последовательной согласованности в соответствии с моделью памяти. В нашем случае это инструкция lock addl $0x0,(%rsp), которая является реализацией барьера StoreLoad. Запоминать эти низкоуровневые подробности реализации необязательно (они могут измениться со временем), важно понимать высокоуровневые закономерности.
Выходит, ничто не мешает нам заменить выражение
private volatile int count = 0;выражением
private volatile int count;Или всё же мешает? Этим вопросом задался Алексей Шипилёв в известной рассылке о многопоточности. Категорически советую к вдумчивому прочтению как пример построения предположений о том, как поведёт себя многопоточный код и модель памяти.
Точку поставил Даг Ли:
But your account is a more careful version of reasoning we've done before to conclude that there is never any reason to explicitly initialize fields to 0/0.0/false/null.
Сама история тянется с 2008 (!) года: Remove unnecessary explicit initialization of volatile variables. К этой же задаче относятся
Remove unnecessary explicit initialization of volatile variables in java.base
Initializing volatile fields to default values should be optimized
Remove unnecessary explicit initialization of volatile variables in security-libs code
Следствием ненужности явного зануления волатильных полей является ненужность зануления объектов атомарных классов:
@OutputTimeUnit(TimeUnit.NANOSECONDS)
@BenchmarkMode(value = Mode.AverageTime)
public class AtomicZeroingBenchmark {
@Benchmark
public Object defaultValue() {
return new AtomicInteger();
}
@Benchmark
public Object explicitValue() {
return new AtomicInteger(0);
}
}Первый метод ожидаемо работает быстрее:
Benchmark Mode Cnt Score Error Units
AtomicZeroingBenchmark.defaultValue avgt 20 3,037 ± 0,100 ns/op
AtomicZeroingBenchmark.explicitValue avgt 20 13,976 ± 0,220 ns/opВот несколько примеров из жизни: раз, два, три.
Теперь вернёмся к ассемблеру. Похожий код находим ниже:
// строка 192
0x00007f137d2278c9: lock addl $0x0,(%rsp) ;*putfield head
; - java.lang.ref.ReferenceQueue::<init>@18 (line 56)
; - o.s.u.CRHM$ReferenceManager::<init>@14 (line 984)
; - o.s.u.CRHM::createReferenceManager@5 (line 207)
; - o.s.u.CRHM$Segment::<init>@16 (line 485)
; - o.s.u.CRHM::<init>@141 (line 184)
17.31% 0x00007f137d2278ce: mov %r10d,0xc(%rdx) ;*putfield queue
; - o.s.u.CRHM$ReferenceManager::<init>@17 (line 984)
; - o.s.u.CRHM::createReferenceManager@5 (line 207)
; - o.s.u.CRHM$Segment::<init>@16 (line 485)
; - o.s.u.CRHM::<init>@141 (line 184)
0x00007f137d2278d2: mov %r12,0x10(%rbp) ;*putfield queueLength
Признаки те же, а виновником является java.lang.ref.ReferenceQueue:
public class ReferenceQueue<T> {
private volatile Reference<? extends T> head = null;
}Поскольку это класс из JDK, мы ничего не можем с ним поделать (в Java 9+ это исправлено).
Едем дальше. В самом конце ассемблерного кода находим следующий участок:
8.00% 0x00007f137d22766a: mov %rbp,%r8
0.22% 0x00007f137d22766d: mov %r10d,0x20(%rbp)
0x00007f137d227671: mov %rbp,%r10
0.66% 0x00007f137d227674: shr $0x9,%r10
0x00007f137d227678: movabs $0x7f138fec8000,%r11
0x00007f137d227682: mov %r12l,(%r11,%r10)
0x00007f137d227686: lock addl $0x0,(%rsp) ;*putfield references
; - o.s.u.CRHM$Segment::<init>@43 (line 487)
; - o.s.u.CRHM::<init>@141 (line 184)
10.51% 0x00007f137d22768b: mov 0x20(%rbp),%r11d ;*getfield references
; - o.s.u.CRHM$Segment::<init>@48 (line 488)
; - o.s.u.CRHM::<init>@141 (line 184)
0.11% 0x00007f137d22768f: mov 0xc(%r11),%r10d ;*arraylength
; - o.s.u.CRHM$Segment::<init>@51 (line 488)
; - o.s.u.CRHM::<init>@141 (line 184)
; implicit exception: dispatches to 0x00007f137d227e91Здесь 8% занимает всё тот же lock addl $0x0,(%rsp), соответствующий записи в волатильное поле в конструкторе Segment:
protected final class Segment extends ReentrantLock {
private volatile Reference<K, V>[] references;
public Segment(int initialCapacity) {
this.references = createReferenceArray(this.initialSize);
}
}volatile здесь нужен для правильной работы в многопоточной среде, так что пропускаем, а вот к 10,51%, соответствующим байт-коду arraylength в строке 488, стоит присмотреться:
protected final class Segment extends ReentrantLock {
private volatile Reference<K, V>[] references;
public Segment(int initialCapacity) {
this.references = createReferenceArray(this.initialSize);
this.resizeThreshold = (int) (this.references.length * getLoadFactor());
}
}Поскольку мы читаем из волатильного поля, то чтение стоит дороже обычного. Решением здесь может стать создание локальной переменной, в которую будет записан массив, возвращаемый из createReferenceArray, и последующее присваивание и чтение из неё.
Замечание
Мне кажется, что здесь мы имеем дело с ошибкой профайлера, исполнение наверняка смогло бы оптимизировать запись и чтение из одного и того же волатильного поля, указанные 10,51% относятся к чтению/записи массива в цикле конструктора CRHM. К тому же я заметил, что ассемблерный профиль может отличаться от ядра к ядру.
Наличие волатильных доступов внутри цикла, а также доступ к массиву через обращение к полю сделали его (доступ) довольно дорогим. Именно к доступу относится самый первый горячий участок ассемблера:
for (int i = 0; i < this.segments.length; i++) { // читаем из поля
this.segments[i] = new Segment(roundedUpSegmentCapacity); // пишем в поле
}Что с этим делать подробно описано в указанной в самом начале статье, так что подробно останавливаться на этом я не буду.
А что с более свежими версиями?
Ничто не мешает нам прогнать этот же бенчмарк на новых версиях Java, например, на 11/17. И тут нас ждёт нежданчик: всё будет работать как прежде, но результаты немного отличаются.
Полный вывод находится тут, и пробежавшись по нему неожиданно обнаруживаем, что из него исчезло всякое упоминание putfield count.
Впервые осознав это я подумал, что оптимизирующий компилятор в старших версиях стал настолько крутым, что смог распознать и выбросить лишнее присваивание волатильному полю значения по умолчанию. Но всё же решил перепроверить и поискать lock addl $0x0. И эта инструкция никуда не делась:
╭ 0x00007f5408368ff5: jmp 0x7f5408369004
│ 0x00007f5408368ff7: mov %rdi,0xfffffffffffffff8(%r10,%r9)
│ ;*putfield sync {reexecute=0 rethrow=0 return_oop=0}
│ ; - j.u.c.l.ReentrantLock::<init>@12 (line 239)
│ ; - o.s.u.CRHM$Segment::<init>@6 (line 484)
│ ; - o.s.u.CRHM::<init>@141 (line 184)
│ 0x00007f5408368ffc: add $0xfffffffffffffff8,%r9
│ 0x00007f5408369000: mov %r9,0x70(%r15)
0.87% ↘ 0x00007f5408369004: movl $0x0,0x14(%rbx)
0.05% 0x00007f540836900b: lock addl $0x0,0xffffffffffffffc0(%rsp)
24.08% 0x00007f5408369011: mov 0x118(%r15),%r13
0x00007f5408369018: mov %r13,%r10Она как и прежде выполняется после вызова конструктора ReentrantLock, дочерним классом которого является ConcurrentReferenceHashMap$Segment. Главная трудность в том, что если разработчик начнёт профилировать на Java 11 и выше, он просто-напросто не увидит указания на конкретную строку в исходном Java-коде!
Исчерпывающего понимания происходящего у меня не было, так что я задал вопрос.
Выяснилось, что оптимизации и перестановки в исполнении JIT-а сломали соотнесение скомпилированного кода и исходников, впрочем, выход есть: выполнив прогон с флагом -XX:MaxInlineLevel=0 (отключает вклеивание) получаем нужное:
0.99% 0x00007fc53836b418: movl $0x0,0x14(%rbp)
0x00007fc53836b41f: lock addl $0x0,0xffffffffffffffc0(%rsp)
;*putfield count {reexecute=0 rethrow=0 return_oop=0}
; - o.s.u.CRHM$Segment::<init>@11 (line 476)
; - o.s.u.CRHM::<init>@141 (line 184)
18.78% 0x00007fc53836b425: mov (%rsp),%rsi
0.10% 0x00007fc53836b429: nopОчевидно, что это так себе решение, ведь в боевом коде глубина вклеивания будет отличаться от используемой в опытах. Кажется, нужно писать в рассылку hotspot-compiler-dev. Ответ не заставил себя долго ждать:
There's never been any guarantee that debuginfo will be complete after transformations. Optimization rewrites things to such an extent that it's not really possible anyway: operations are reorganized and combined in such a way that the relationship between incoming bytecode and generated code is not 1:1.
Краткий перевод: вам никто ничего не обещал, но вы держитесь там! Всего доброго и отличного профилирования :).
Замечание
Возможно, где-то в методологии исследования была допущена ошибка, и я подкладывал собранный из исходников Java 8 hsdis в процесс, запущенный на Java 11. Сегодня это кажется мне наиболее вероятным, ибо когда я собирал hsdis из исходников JDK 17 с самым свежим binutils и пользовался локальной сборкой для профилирования маппинг работал идеально. Если вы столкнулись с похожей проблемой — попробуйте взять исходники стабильной версии вашего JDK (и запускать приложение на нём), собрать на нём hsdis для вашей платформы и использовать.
Указанный способ обхода данного ограничения (-XX:MaxInlineLevel=0) категорически не советую использовать в качестве единственного средства диагностики, потому что отключение вклеивания может сильно исказить профиль. Доказать это можно на простом примере:
@BenchmarkMode(Mode.AverageTime)
@OutputTimeUnit(TimeUnit.NANOSECONDS)
public class TurnOffInliningBenchmark {
@Benchmark
public int calculate() {
return calculate(200);
}
@Benchmark
@Fork(jvmArgsAppend = {"-XX:MaxInlineLevel=0"})
public int calculateNoInlining() {
return calculate(200);
}
private Integer calculate(int length) {
Integer sum = 0;
for (int i = 0; i < length; i++) {
sum += i;
}
return sum;
}
}Если запустить этот бенчмарк на старших версиях (например, 17), то метод calculateNoInlining() проиграет с чудовищным отрывом как по времени, так и по потреблению памяти:
Benchmark Score Error Units
TurnOffInliningBenchmark.calculate 51,099 ± 0,842 ns/op
TurnOffInliningBenchmark.calculate:·gc.alloc.rate 0,001 ± 0,001 MB/sec
TurnOffInliningBenchmark.calculate:·gc.alloc.rate.norm ≈ 10⁻⁴ B/op
TurnOffInliningBenchmark.calculate:·gc.count ≈ 0 counts
TurnOffInliningBenchmark.calculateNoInlining 766,289 ± 17,697 ns/op
TurnOffInliningBenchmark.calculateNoInlining:·gc.alloc.rate 2443,419 ± 54,399 MB/sec
TurnOffInliningBenchmark.calculateNoInlining:·gc.alloc.rate.norm 2944,301 ± 0,014 B/op
TurnOffInliningBenchmark.calculateNoInlining:·gc.churn.G1_Eden_Space 2437,723 ± 70,539 MB/sec
TurnOffInliningBenchmark.calculateNoInlining:·gc.churn.G1_Eden_Space.norm 2937,362 ± 52,498 B/op
TurnOffInliningBenchmark.calculateNoInlining:·gc.churn.G1_Survivor_Space 0,015 ± 0,002 MB/sec
TurnOffInliningBenchmark.calculateNoInlining:·gc.churn.G1_Survivor_Space.norm 0,018 ± 0,003 B/op
TurnOffInliningBenchmark.calculateNoInlining:·gc.count 596,000 counts
TurnOffInliningBenchmark.calculateNoInlining:·gc.time 469,000 msПрофиль, разумеется, будет сильно искажён.
Но и это ещё не всё!
К счастью для меня, я не ограничился одним-двумя прогонами, и запустив в очередной раз бенчмарк c Java 11 внезапно обнаружил в выводе искомый putfield count!
0.97% ↘ 0x00007f6ff436a099: mov 0x10(%rsp),%r10
0.05% 0x00007f6ff436a09e: movl $0x0,0x14(%r10)
0x00007f6ff436a0a6: lock addl $0x0,0xffffffffffffffc0(%rsp)
;*putfield count {reexecute=0 rethrow=0 return_oop=0}
; - o.s.u.CRHM$Segment::<init>@11 (line 476)
25.36% 0x00007f6ff436a0ac: mov 0x8(%rsp),%r10Тут я окончательно растерялся. После несколько дополнительных прогонов картинка немного прояснилась: указание на putfield count при запуске в обычном режиме (иными словами без дополнительных настроек ВМ) появлялось в выводе случайным образом. Тогда было принято решение собрать статистику:
#!/bin/bash
for i in {1..100}
do
touch "$i".txt
/usr/lib/jvm/java-11-openjdk-amd64/bin/java \
-jar ../target/benchmarks.jar CRHMBenchmark \
-f 1 -wi 5 -i 1 -w 1s -r 1s -prof perfasm \
-jvmArgsAppend "-XX:+UnlockDiagnosticVMOptions -XX:+PrintAssembly" > "$i".txt
doneВ этом скрипте мы выполняем 100 прогонов и вывод каждого пишем в отдельный файл. После переходим в папку с файлами и считаем количество вхождений искомой строки:
#!/bin/bash
declare -i count=0;
declare -i count_in_file=0;
for i in *.txt;
do
count_in_file=$((`grep -o -i 'putfield count' $i | wc -l`));
count=$((count + count_in_file));
done
echo $countУ меня получилось так:
0.90% 0x00007f2513331eae: lock addl $0x0,-0x40(%rsp) ;*putfield count {reexecute=0 rethrow=0 return_oop=0}
0.03% 0x00007fc1bbb924ab: lock addl $0x0,-0x40(%rsp) ;*putfield count {reexecute=0 rethrow=0 return_oop=0}
0.07% 0x00007f9972d021ae: lock addl $0x0,-0x40(%rsp) ;*putfield count {reexecute=0 rethrow=0
...
0.42% 0x00007f99b03999ae: lock addl $0x0,-0x40(%rsp) ;*putfield count {reexecute=0 rethrow=0 return_oop=0}
24Проще говоря в 24 случаях из 100 компилятор сохранил указание на putfield count. Не очень-то обнадёживает, правда? Получается, никогда нельзя полагаться на один прогон! Ведь там часть данных может потеряться и вы тупо не увидите ссылку на горячее место в исходном Java-коде. Поэтому советую выполнять 10-20 прогонов с выводом в файл и просматривать каждый отдельно.
В сухом остатке
Итак, чего же мы добились нашими измененниям (раз, два):
J8 SB 2.1.1 J8 SB 2.3.11 J11 SB 2.3.11
count Units
dto 1 14.0 ± 0.1 5.8 ± 0.3 6.2 ± 0.1 us/op
proj 1 17.2 ± 0.2 10.3 ± 0.2 10.1 ± 0.0 us/op
dto 100 45.6 ± 0.7 35.0 ± 0.2 31.0 ± 0.5 us/op
proj 100 216.9 ± 0.4 199.6 ± 0.5 180.8 ± 0.8 us/opЗдесь J8 и J11 — это Java 8/11, а SB — Spring Boot соответствующей версии.
Общие выводы для разработчика
в сложный случаях, когда неясно, куда именно смотреть, не бойтесь нырнуть глубже и посмотреть ассемблер
помните, что все профилировщики допускают погрешность, см. прекрасные доклады Nitsan Wakart - Profilers are lying hobbitses и Андрей Паньгин - Искусство Java профилирования
не стесняйтесь задавать вопросы — объясняя его другим вы сами лучше понимаете стоящую перед вами задачу
Практические выводы для разработчика
выпиливайте присваивание значений по-умолчанию волатильным полям в ваших приложениях, это даст некоторый прирост и ничего не сломает (а если всё же сломает, то обязательно напишите об этом в http://cs.oswego.edu/pipermail/concurrency-interest, это станет сенсацией). Также ставьте палец вверх этим задачам:
https://youtrack.jetbrains.com/issue/IDEA-243752
https://youtrack.jetbrains.com/issue/IDEA-251885
Так на них быстрее обратят внимание ;)пользуйтесь флагами виртуальной машины при прогонах, они помогут вам сузить область поиска. Например, если вы грешите на компилятор — пробуйте запуск с
-Xint/-XX:TieredStopAtLevel=1или уже упомянутый-XX:MaxInlineLevel=0, однако помните, что они могут как помочь, так и запутать. Пробуйте разные сочетания для получения достоверных результатов.выполняйте множество прогонов и собирайте статистику
Главный вывод для разработчика (прямиком из JMH)
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.
На этом всё, надеюсь, заметка была интересной и полезной вам. До новых встреч :)
ris58h
Спасибо. Поход серьёзный.
Интересно что в итоге с проекциями стало? Отказались?
tsypanov Автор
Да, DTO наше всё, по крайней мере с JPA.