Привет, сегодня будет объёмная и обстоятельная статья о низкоуровневом профилировании и диагностике производительности. Многократно в комментариях к докладам и статьям пользователи высказывали пожелание увидеть не просто перечисление шаблонов "как нужно" и "как не нужно", а целостную историю. Поэтому вот вам статья про конкретный кейс и его историю :). Не удивляйтесь, что начнём мы с 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% занимает конструктор ConcurrentReferenceHashMap

  • 25% занимает 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. К этой же задаче относятся

Следствием ненужности явного зануления волатильных полей является ненужность зануления объектов атомарных классов:

@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.

На этом всё, надеюсь, заметка была интересной и полезной вам. До новых встреч :)

Комментарии (2)


  1. ris58h
    08.06.2023 18:21

    Спасибо. Поход серьёзный.

    Интересно что в итоге с проекциями стало? Отказались?


    1. tsypanov Автор
      08.06.2023 18:21
      +1

      Да, DTO наше всё, по крайней мере с JPA.