Работая над темой низкоуровневого профилирования, я обнаружил отсутствие подробного руководства по настройке окружения и сбору материала. Всё пришлось делать самому путём проб и ошибок. Итогом стала эта статья, в которой я по шагам описал профилирование кода, горячее место в котором не в силах обнаружить не только привычный VisualVM, но и сверхточные инструменты вроде async-profiler-а. В качестве примера использован код статьи The volatile read surprise.

Постановка задачи

Когда-то давно прочитав статью The volatile read surprise мне стало любопытно, как именно автор пришёл к сделанным в статье выводам. Для начала кратко ознакомимся с матчастью:

Подопытный код
@BenchmarkMode(Mode.AverageTime)
@OutputTimeUnit(TimeUnit.NANOSECONDS)
@State(Scope.Thread)
public class LoopyBenchmarks {
  @Param({ "32", "1024", "32768" })
  int size;

  byte[] bunn;

  @Setup
  public void prepare() {
    bunn = new byte[size];
  }

  @Benchmark
  public void goodOldLoop(Blackhole fox) {
    for (int y = 0; y < bunn.length; y++) { // good old C style for (the win?)
      fox.consume(bunn[y]);
    }
  }

  @Benchmark
  public void sweetLoop(Blackhole fox) {
    for (byte bunny : bunn) { // syntactic sugar loop goodness
      fox.consume(bunny);
    }
  }
}

Запустив данный бенчмарк мы обнаружим существенную разницу в скорости работы:

Benchmark              (size)     Score   Error  Units

goodOldLoop               32     46.630   0.097  ns/op
goodOldLoop             1024   1199.338   0.705  ns/op
goodOldLoop            32768  37813.600  56.081  ns/op

sweetLoop                 32     19.304   0.010  ns/op
sweetLoop               1024    475.141   1.227  ns/op
sweetLoop              32768  14295.800  36.071  ns/op

Где же в коде горячее место? Как понять, что именно тормозит в обычном счётном цикле? Почему счётный цикл оказался в два раза медленнее, чем for-each, который после компиляции превращается в почти тот же самый счётный цикл.

Как проводилось исследование

The assembly code for the goodOldLoopis long and painful to read through, and that in itself is a clue.

Вывод автора

The thing that stands out (when the assembly smoke clears) is that bunn is loaded on every iteration, bunn.length is loaded and an array boundary check happens. This is surely a terrible way to interpret a for loop. The culprit turns out to be a volatile read in Blackhole.consume(). ... A volatile load of one value requires the JVM to load all subsequent loads from memory to force happens before relationships, in this case the field bunn is reloaded on every iteration of the loop.

Получается, используя -XX:+PrintAssembly можно получить вывод всего ассемблерного кода, который в сыром виде выглядит примерно вот так:

Это только малая часть
[Verified Entry Point]
  0x00007f6605205020: mov    %eax,-0x14000(%rsp)
  0x00007f6605205027: push   %rbp
  0x00007f6605205028: sub    $0x30,%rsp         ;*synchronization entry
                                                ; - org.tsypanov.sb.misc.LoopyBenchmarks::goodOldLoop@-1 (line 24)

  0x00007f660520502c: mov    %rdx,0x8(%rsp)
  0x00007f6605205031: mov    %rsi,(%rsp)
  0x00007f6605205035: mov    0x10(%rsi),%r11d   ;*getfield bunn
                                                ; - org.tsypanov.sb.misc.LoopyBenchmarks::goodOldLoop@4 (line 24)

  0x00007f6605205039: mov    0xc(%r12,%r11,8),%r10d  ; implicit exception: dispatches to 0x00007f66052050e5
  0x00007f660520503e: test   %r10d,%r10d
  0x00007f6605205041: jle    0x00007f6605205084  ;*if_icmpge
                                                ; - org.tsypanov.sb.misc.LoopyBenchmarks::goodOldLoop@8 (line 24)

  0x00007f6605205043: test   %rdx,%rdx
  0x00007f6605205046: je     0x00007f66052050a5
  0x00007f6605205048: xor    %ebp,%ebp
  0x00007f660520504a: nopw   0x0(%rax,%rax,1)   ;*aload_1
                                                ; - org.tsypanov.sb.misc.LoopyBenchmarks::goodOldLoop@11 (line 25)

  0x00007f6605205050: mov    0xc(%r12,%r11,8),%r10d  ; implicit exception: dispatches to 0x00007f66052050c6
  0x00007f6605205055: cmp    %r10d,%ebp
  0x00007f6605205058: jae    0x00007f6605205090
  0x00007f660520505a: lea    (%r12,%r11,8),%r10
  0x00007f660520505e: movsbl 0x10(%r10,%rbp,1),%edx  ;*baload
                                                ; - org.tsypanov.sb.misc.LoopyBenchmarks::goodOldLoop@17 (line 25)

И вроде бы тут есть указание на байт-код, соответствующий тому или иному набору инструкций, и даже есть номер строки в исходной Java-коде, но совершенно непонятно, где и на что тратится львиная доля времени! Хотелось бы избавиться от нужды вычитывать простыни ассемблера и сразу получить вменяемый профиль.

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

Ныряем

Батискафом нам послужит org.openjdk.jmh.profile.LinuxPerfAsmProfiler, доступный из коробки вместе с JMH. Для наглядности профилировщик подключен прямо в коде (доступен также вариант с аргументом командной строки -prof perfasm):

public class BenchmarkRunner {

  public static void main(String[] args) throws RunnerException {
    Options opt = new OptionsBuilder()
      .include(LoopyBenchmark.class.getSimpleName())
      .warmupIterations(10)
      .warmupTime(TimeValue.seconds(1))
      .measurementIterations(1)
      .measurementTime(TimeValue.seconds(10))
      .addProfiler(LinuxPerfAsmProfiler.class)
      .forks(1) //0 makes debugging possible
      .build();

    new Runner(opt).run();
  }
}

Обратите внимание, я намеренно выставил значение forks (количество отдельных Java-процессов) равным 1. Обычно для достижения высокой точности измерений требуется несколько отдельных Java-процессов, в данном же случае нужен один, т. к. адреса ассемблерных инструкций могут меняться от прогона к прогону, что отдельно оговорено в документации.

Запускаем и переходим в консоль:

[Cannot run program "perf": error=2, No such file or directory]
Exception in thread "main" org.openjdk.jmh.runner.ProfilersFailedException:
Profilers failed to initialize, exiting.
    at org.openjdk.jmh.runner.Runner.internalRun(Runner.java:244)
    at org.openjdk.jmh.runner.Runner.run(Runner.java:209)

Итак, первое препятствие: отсутствует приложение perf. Тут просто: беглый поиск в Яндексе даёт подсказку:

The perf utility can be found in the linux-tools package

Следовательно:

$ sudo apt-get install linux-tools-generic

Заводим ещё раз:

[WARNING: perf not found for kernel 5.4.0-42

  You may need to install the following packages for this specific kernel:
    linux-tools-5.4.0-42-generic
    linux-cloud-tools-5.4.0-42-generic

  You may also want to install one of the following packages to keep up to date:
    linux-tools-generic
    linux-cloud-tools-generic
]
Exception in thread "main" org.openjdk.jmh.runner.ProfilersFailedException: Profilers failed to initialize, exiting.

Хм, кажется нужный нам perf не доехал. Исправляем:

$ sudo apt-get install linux-tools-5.4.0-42-generic

Здесь окончание 5.4.0-42-generic должно соответствовать версии вашего ядра. Обратите внимание: если после очередного sudo apt-get dist-upgrade у вас обновится ядро, то linux-tools тоже нужно будет обновить.

Пускаем ещё раз:

[Error:
You may not have permission to collect stats.

Consider tweaking /proc/sys/kernel/perf_event_paranoid,
which controls use of the performance events system by
unprivileged users (without CAP_SYS_ADMIN).

The current value is 3:

  -1: Allow use of (almost) all events by all users
      Ignore mlock limit after perf_event_mlock_kb without CAP_IPC_LOCK
>= 0: Disallow ftrace function tracepoint by users without CAP_SYS_ADMIN
      Disallow raw tracepoint access by users without CAP_SYS_ADMIN
>= 1: Disallow CPU event access by users without CAP_SYS_ADMIN
>= 2: Disallow kernel profiling by users without CAP_SYS_ADMIN

To make this setting permanent, edit /etc/sysctl.conf too, e.g.:
    kernel.perf_event_paranoid = -1
]

Так, перф завёлся, уже хорошо. Ошибка, которую мы видим, связана с невозможностью получить доступ к событиям на уровне ядра. Она хорошо знакома тем, кто работает с async-profiler-ом, и в Линуксе исправляется обычно так:

$ sudo sh -c 'echo 1 > /proc/sys/kernel/perf_event_paranoid'
Для ленивых покажу один финт ушами

Делай раз: выбираем запуск бенчмарка с профилировщиком

Делай два: нажимаем по ссылке во всплывающей ошибке

Делай три: соглашаемся и вводим пароль

Ну теперь-то точно должно завестись! И действительно, всё заработало. Бенчмарк дорабатывает своё, мы проматываем консоль и… очередной облом:

ERROR: No address lines detected in assembly capture. Make sure your JDK is properly
configured to print generated assembly. The most probable cause for this failure is
that hsdis is not available, or resides at the wrong path within the JDK. Try to run
the same JDK with -XX:+PrintAssembly with a simple non-JMH program and look for
warning messages. For details, see the link below:
    https://wiki.openjdk.java.net/display/HotSpot/PrintAssembly

Прочитав руководство по указанной ссылке возвращаемся к BenchmarkRunner-у и дописываем требуемое:

Options opt = new OptionsBuilder()
  .include(ConcurrentReferenceHashMapBenchmark.class.getSimpleName())
  .warmupIterations(10)
  .warmupTime(TimeValue.seconds(1))
  .measurementIterations(10)
  .measurementTime(TimeValue.seconds(10))
  .addProfiler(LinuxPerfAsmProfiler.class)
  .jvmArgsAppend(
    "-XX:+UnlockDiagnosticVMOptions",           // <-------
    "-XX:+PrintAssembly"
  )
  .forks(1)
  .build();

new Runner(opt).run();

Но и этого недостаточно, ведь кроме прочего нам нужно установить в ВМ плагин hsdis для дизассемблирования, при чём руководство по ссылке выше предлагает собрать его из исходников. К счастью для нас добрые люди уже всё сделали, поэтому готовую сборку можно скачать с ГитХаба. Обратите внимание, что в моём случае я загружаю hsdis-amd64.so. В этом же репозитории находится hsdis-amd64.dylib, который пригодится для пользователей Маков.

Теперь копируем его в папку, в которой находится файл libjvm.so, у меня с openjdk-8 получается так:

$ find /usr -name libjvm.so
/usr/lib/jvm/java-8-openjdk-amd64/jre/lib/amd64/server/libjvm.so

$ sudo cp hsdis-amd64.so /usr/lib/jvm/java-8-openjdk-amd64/jre/lib/amd64/server/

Допустим, у вас иная архитектура и очень хочется профилировать ассемблер. Что делать? Самый верный вариант - собраться самостоятельно. Здесь два варианта:

1) следовать руководству, изложенному в https://github.com/liuzhengyang/hsdis
2) собрать hsdis из поставляемых вместе с OpenJDK исходников

Во втором случае нужно скачать OpenJDK и выполнить следующие команды:

# предпожим, вы выкачали проект в ~/IdeaProjects/jdk14
$ cd ~/IdeaProjects/jdk14/src/utils/hsdis/
# качаем свежий binutils (в первом варианте используется версия 2.26)
$ wget http://ftpmirror.gnu.org/gnu/binutils/binutils-2.35.tar.gz
# разжимаем
$ tar zxvf binutils-2.35.tar.gz
# задаём переменную окружения BINUTILS
$ export BINUTILS=binutils-2.35
# собираем под amd64, если нужно собрать под i356, то make ARCH=i356 и т.п.
$ make ARCH=amd64
# копируем 64 битную линуксовую сборку в ту же папку, где лежит libjvm.so
$ sudo cp build/linux/amd64/hsdis-amd64.so /usr/lib/jvm/java-8-openjdk-amd64/jre/lib/amd64/server/

И вот после запуска мы, наконец, видим тот самый ассемблер, исполняемый процессором. Вывод показывает наличие двух горячих мест в коде (целиком тут):

....[Hottest Methods (after inlining)]..............................................................
 54.56%         C2, level 4  org.tsypanov.sb.misc.jmh_generated.LoopyBenchmarks_goodOldLoop_jmhTest::goodOldLoop_avgt_jmhStub, version 584
 43.41%         C2, level 4  org.openjdk.jmh.infra.Blackhole::consume, version 561
  0.59%   [kernel.kallsyms]  native_write_msr
  0.08%   [kernel.kallsyms]  do_syscall_64
  0.06%   [kernel.kallsyms]  entry_SYSCALL_64
  0.04%           libjvm.so  fileStream::write
  0.03%           libjvm.so  is_error_reported
  0.02%   [kernel.kallsyms]  _raw_spin_lock_irq
  0.02%   [kernel.kallsyms]  syscall_return_via_sysret
  0.02%   [kernel.kallsyms]  prepare_exit_to_usermode
  0.02%   [kernel.kallsyms]  __fget
  0.02%           libjvm.so  SpinPause
  0.02%      hsdis-amd64.so  print_insn
  0.02%           libjvm.so  outputStream::print
  0.02%   [kernel.kallsyms]  iov_iter_copy_from_user_atomic
  0.02%   [kernel.kallsyms]  vfs_write
  0.02%   [kernel.kallsyms]  kill_fasync
  0.02%   [kernel.kallsyms]  __x64_sys_write
  0.02%   [kernel.kallsyms]  psi_task_change
  0.02%        libc-2.27.so  __GI___libc_write
  0.94%  <...other 81 warm methods...>
....................................................................................................
 99.99%  <totals>
[Hottest Region 1]
C2, level 4, org.tsypanov.sb.misc.jmh_generated.LoopyBenchmarks_goodOldLoop_jmhTest::goodOldLoop_avgt_jmhStub, version 584 (130 bytes)

                0x00007fb4512539bd: mov    0x50(%rsp),%r9
                0x00007fb4512539c2: movzbl 0x94(%r9),%r11d    ;*getfield isDone
                                                              ; - org.tsypanov.sb.misc.jmh_generated.LoopyBenchmarks_goodOldLoop_jmhTest::goodOldLoop_avgt_jmhStub@27 (line 188)
                                                              ; implicit exception: dispatches to 0x00007fb451253bb5
                0x00007fb4512539ca: test   %r11d,%r11d
                0x00007fb4512539cd: jne    0x00007fb451253a85  ;*ifeq
                                                              ; - org.tsypanov.sb.misc.jmh_generated.LoopyBenchmarks_goodOldLoop_jmhTest::goodOldLoop_avgt_jmhStub@30 (line 188)
                0x00007fb4512539d3: mov    $0x1,%ebx
         ?      0x00007fb4512539d8: jmp    0x00007fb451253a45
         ¦      0x00007fb4512539da: nopw   0x0(%rax,%rax,1)
  9.48%  ¦     0x00007fb4512539e0: mov    0x50(%rsp),%r9
  0.02%  ¦ ¦    0x00007fb4512539e5: mov    (%rsp),%rbx        ;*aload_1
         ¦ ¦                                                  ; - org.tsypanov.sb.misc.LoopyBenchmarks::goodOldLoop@11 (line 25)
         ¦ ¦                                                  ; - org.tsypanov.sb.misc.jmh_generated.LoopyBenchmarks_goodOldLoop_jmhTest::goodOldLoop_avgt_jmhStub@17 (line 186)
  0.82%  ¦ ¦   0x00007fb4512539e9: mov    0xc(%r12,%r11,8),%r8d  ; implicit exception: dispatches to 0x00007fb451253b2d
  0.08%  ¦ ¦ ¦  0x00007fb4512539ee: cmp    %r8d,%ebp
  0.01%  ¦?¦ ¦  0x00007fb4512539f1: jae    0x00007fb451253a66
  9.32%  ¦¦¦ ¦  0x00007fb4512539f3: mov    %rbx,(%rsp)
  0.03%  ¦¦¦ ¦  0x00007fb4512539f7: mov    %r9,0x50(%rsp)
  0.76%  ¦¦¦ ¦  0x00007fb4512539fc: lea    (%r12,%r11,8),%r10
  0.02%  ¦¦¦ ¦  0x00007fb451253a00: movsbl 0x10(%r10,%rbp,1),%edx  ;*baload
         ¦¦¦ ¦                                                ; - org.tsypanov.sb.misc.LoopyBenchmarks::goodOldLoop@17 (line 25)
         ¦¦¦ ¦                                                ; - org.tsypanov.sb.misc.jmh_generated.LoopyBenchmarks_goodOldLoop_jmhTest::goodOldLoop_avgt_jmhStub@17 (line 186)
  9.52%  ¦¦¦ ¦  0x00007fb451253a06: mov    0x18(%rsp),%rsi
  0.06%  ¦¦¦ ¦  0x00007fb451253a0b: callq  0x00007fb451045de0  ; OopMap{[80]=Oop [88]=Oop [96]=Oop [24]=Oop off=240}
         ¦¦¦ ¦                                                ;*invokevirtual consume
         ¦¦¦ ¦                                                ; - org.tsypanov.sb.misc.LoopyBenchmarks::goodOldLoop@18 (line 25)
         ¦¦¦ ¦                                                ; - org.tsypanov.sb.misc.jmh_generated.LoopyBenchmarks_goodOldLoop_jmhTest::goodOldLoop_avgt_jmhStub@17 (line 186)
         ¦¦¦ ¦                                                ;   {optimized virtual_call}
  6.61%  ¦¦¦ ¦  0x00007fb451253a10: mov    0x60(%rsp),%r10
  9.18%  ¦¦¦ ¦  0x00007fb451253a15: mov    0x10(%r10),%r11d   ;*getfield bunn
         ¦¦¦ ¦                                                ; - org.tsypanov.sb.misc.LoopyBenchmarks::goodOldLoop@4 (line 24)
         ¦¦¦ ¦                                                ; - org.tsypanov.sb.misc.jmh_generated.LoopyBenchmarks_goodOldLoop_jmhTest::goodOldLoop_avgt_jmhStub@17 (line 186)
  0.15%  ¦¦¦ ¦  0x00007fb451253a19: mov    0xc(%r12,%r11,8),%r8d  ; implicit exception: dispatches to 0x00007fb451253b3d
  6.78%  ¦¦¦ ¦  0x00007fb451253a1e: inc    %ebp               ;*iinc
         ¦¦¦ ¦                                                ; - org.tsypanov.sb.misc.LoopyBenchmarks::goodOldLoop@21 (line 24)
         ¦¦¦ ¦                                                ; - org.tsypanov.sb.misc.jmh_generated.LoopyBenchmarks_goodOldLoop_jmhTest::goodOldLoop_avgt_jmhStub@17 (line 186)
  0.01%  ¦¦¦ ¦  0x00007fb451253a20: cmp    %r8d,%ebp
  0.02%  ¦¦? ¦  0x00007fb451253a23: jl     0x00007fb4512539e0
  0.41%  ¦¦  ¦  0x00007fb451253a25: mov    0x50(%rsp),%r9
  0.07%  ¦¦  ¦  0x00007fb451253a2a: mov    (%rsp),%rbx        ;*if_icmpge
         ¦¦  ¦                                                ; - org.tsypanov.sb.misc.LoopyBenchmarks::goodOldLoop@8 (line 24)
         ¦¦  ¦                                                ; - org.tsypanov.sb.misc.jmh_generated.LoopyBenchmarks_goodOldLoop_jmhTest::goodOldLoop_avgt_jmhStub@17 (line 186)
  0.02%  ¦¦ ¦  0x00007fb451253a2e: movzbl 0x94(%r9),%r10d    ;*getfield isDone
         ¦¦ ¦¦                                                ; - org.tsypanov.sb.misc.jmh_generated.LoopyBenchmarks_goodOldLoop_jmhTest::goodOldLoop_avgt_jmhStub@27 (line 188)
  0.07%  ¦¦ ¦¦  0x00007fb451253a36: add    $0x1,%rbx          ; OopMap{r9=Oop [88]=Oop [96]=Oop [24]=Oop off=282}
         ¦¦ ¦¦                                                ;*ifeq
         ¦¦ ¦¦                                                ; - org.tsypanov.sb.misc.jmh_generated.LoopyBenchmarks_goodOldLoop_jmhTest::goodOldLoop_avgt_jmhStub@30 (line 188)
  0.28%  ¦¦ ¦¦  0x00007fb451253a3a: test   %eax,0x1837a5c0(%rip)        # 0x00007fb4695ce000
         ¦¦ ¦¦                                                ;   {poll}
  0.01%  ¦¦ ¦¦  0x00007fb451253a40: test   %r10d,%r10d
         ¦¦ ¦¦  0x00007fb451253a43: jne    0x00007fb451253a8a  ;*aload
         ¦¦ ¦¦                                                ; - org.tsypanov.sb.misc.jmh_generated.LoopyBenchmarks_goodOldLoop_jmhTest::goodOldLoop_avgt_jmhStub@13 (line 186)
  0.03%  ¦ ¦¦  0x00007fb451253a45: mov    0x60(%rsp),%r10
  0.02%   ¦ ¦¦  0x00007fb451253a4a: mov    0x10(%r10),%r11d   ;*getfield bunn
          ¦ ¦¦                                                ; - org.tsypanov.sb.misc.LoopyBenchmarks::goodOldLoop@4 (line 24)
          ¦ ¦¦                                                ; - org.tsypanov.sb.misc.jmh_generated.LoopyBenchmarks_goodOldLoop_jmhTest::goodOldLoop_avgt_jmhStub@17 (line 186)
  0.35%   ¦ ¦¦  0x00007fb451253a4e: mov    0xc(%r12,%r11,8),%r10d  ; implicit exception: dispatches to 0x00007fb451253b4d
  0.06%   ¦ ¦¦  0x00007fb451253a53: test   %r10d,%r10d
          ¦ ?¦  0x00007fb451253a56: jle    0x00007fb451253a2e  ;*if_icmpge
          ¦  ¦                                                ; - org.tsypanov.sb.misc.LoopyBenchmarks::goodOldLoop@8 (line 24)
          ¦  ¦                                                ; - org.tsypanov.sb.misc.jmh_generated.LoopyBenchmarks_goodOldLoop_jmhTest::goodOldLoop_avgt_jmhStub@17 (line 186)
  0.11%   ¦  ¦  0x00007fb451253a58: mov    0x18(%rsp),%r10
          ¦  ¦  0x00007fb451253a5d: test   %r10,%r10
          ¦  ¦  0x00007fb451253a60: je     0x00007fb451253ab4  ;*aload_1
          ¦  ¦                                                ; - org.tsypanov.sb.misc.LoopyBenchmarks::goodOldLoop@11 (line 25)
          ¦  ¦                                                ; - org.tsypanov.sb.misc.jmh_generated.LoopyBenchmarks_goodOldLoop_jmhTest::goodOldLoop_avgt_jmhStub@17 (line 186)
  0.24%   ¦  ¦  0x00007fb451253a62: xor    %ebp,%ebp
          ¦  ?  0x00007fb451253a64: jmp    0x00007fb4512539e9
               0x00007fb451253a66: mov    $0xffffffe4,%esi
                0x00007fb451253a6b: mov    %r9,0x50(%rsp)
                0x00007fb451253a70: mov    %rbx,0x8(%rsp)
                0x00007fb451253a75: mov    %r11d,0x28(%rsp)
                0x00007fb451253a7a: nop
                0x00007fb451253a7b: callq  0x00007fb4510453e0  ; OopMap{[80]=Oop [88]=Oop [96]=Oop [24]=Oop [40]=NarrowOop off=352}
                                                              ;*baload

По формату: слева мы видим долю времени, которую занимает тот или иной набор инструкций ассемблера, слева - сами инструкции и соответствующий им байт-код, а ещё левее - точное указание на метод и строку в исходном Java-коде!

Важное здесь находится в строках 14, 23, 33, означающих, соответственно, чтение this, чтение поля bunnдля получения длины массива, а также чтение этого же поля для передачи отдельного байта в Blackhole::consume.

[Hottest Region 2]
C2, level 4, org.openjdk.jmh.infra.Blackhole::consume, version 561 (53 bytes)

            # parm0:    rdx       = byte
            #           [sp+0x30]  (sp of caller)
            0x00007fb45123b7a0: mov    0x8(%rsi),%r10d
            0x00007fb45123b7a4: shl    $0x3,%r10
            0x00007fb45123b7a8: cmp    %r10,%rax
            0x00007fb45123b7ab: jne    0x00007fb451045ba0  ;   {runtime_call}
            0x00007fb45123b7b1: data16 xchg %ax,%ax
            0x00007fb45123b7b4: nopl   0x0(%rax,%rax,1)
            0x00007fb45123b7bc: data16 data16 xchg %ax,%ax
          [Verified Entry Point]
  0.95%     0x00007fb45123b7c0: mov    %eax,-0x14000(%rsp)
  9.97%     0x00007fb45123b7c7: push   %rbp
  1.11%     0x00007fb45123b7c8: sub    $0x20,%rsp         ;*synchronization entry
                                                          ; - org.openjdk.jmh.infra.Blackhole::consume@-1 (line 322)
  9.93%     0x00007fb45123b7cc: movsbl 0xd0(%rsi),%r10d   ;*getfield b1
                                                          ; - org.openjdk.jmh.infra.Blackhole::consume@1 (line 322)
  0.11%     0x00007fb45123b7d4: mov    %edx,%r8d
  0.83%     0x00007fb45123b7d7: xor    %r10d,%r8d         ;*ixor
                                                          ; - org.openjdk.jmh.infra.Blackhole::consume@12 (line 324)
  0.08%     0x00007fb45123b7da: movsbl 0xd2(%rsi),%r11d
  9.38%     0x00007fb45123b7e2: xor    %edx,%r11d         ;*ixor
                                                          ; - org.openjdk.jmh.infra.Blackhole::consume@15 (line 324)
  0.06%     0x00007fb45123b7e5: cmp    %r11d,%r8d
         ?  0x00007fb45123b7e8: je     0x00007fb45123b7f6  ;*if_icmpne
         ¦                                                ; - org.openjdk.jmh.infra.Blackhole::consume@16 (line 324)
  0.81%  ¦  0x00007fb45123b7ea: add    $0x20,%rsp
  0.01%  ¦  0x00007fb45123b7ee: pop    %rbp
 10.09%  ¦  0x00007fb45123b7ef: test   %eax,0x1839280b(%rip)        # 0x00007fb4695ce000
         ¦                                                ;   {poll_return}
  0.08%  ¦  0x00007fb45123b7f5: retq
           0x00007fb45123b7f6: mov    %rsi,%rbp
            0x00007fb45123b7f9: mov    %edx,(%rsp)
            0x00007fb45123b7fc: mov    %r8d,0x4(%rsp)
            0x00007fb45123b801: mov    %r11d,0x8(%rsp)
            0x00007fb45123b806: mov    $0xffffff65,%esi
            0x00007fb45123b80b: callq  0x00007fb4510453e0  ; OopMap{rbp=Oop off=112}
                                                          ;*if_icmpne
                                                          ; - org.openjdk.jmh.infra.Blackhole::consume@16 (line 324)
                                                          ;   {runtime_call}

Здесь без неожиданностей: львиная доля времени тратится на волатильный доступ. Таким образом, мы подтвердили вывод автора: волатильный доступ внутри цикла, перебирающего массив путём обращения к полю сильно бьёт по производительности из-за требований JMM обеспечить последовательную согласованность всех чтений. На деле это означает отключение кэширования поля и чтение его из памяти при каждом проходе по циклу.

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