Работая над темой низкоуровневого профилирования, я обнаружил отсутствие подробного руководства по настройке окружения и сбору материала. Всё пришлось делать самому путём проб и ошибок. Итогом стала эта статья, в которой я по шагам описал профилирование кода, горячее место в котором не в силах обнаружить не только привычный 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 обеспечить последовательную согласованность всех чтений. На деле это означает отключение кэширования поля и чтение его из памяти при каждом проходе по циклу.
На этом всё, надеюсь, заметка станет полезной для вас и вы будете чаще смотреть в самую глубину вашего кода и искать новые возможности для улучшений. До новых встреч.
foxin
Если убрать попытки автора завести профайлер (ну камон, это же погуглить по SO) и свернуть ассемблерные листинги — то статья помещается в 1 экран =)
tsypanov Автор
Собственно, статья как раз о том, как его завести — в первый раз это было очень больно и заняло очень много времени. Чтение профиля, имхо, куда легче, но и там есть нюансы, когда-нибудь я об этом ещё напишу