В данной статье я кратко описываю диагностические флаги JVM HotSpot, с помощью которых можно посмотреть на результаты работы JIT-компиляторов JVM. Эта информация поможет в оптимизации приложения для low-latency и в поиске узких мест.
PrintCompilation
Чтобы посмотреть, как и когда JIT-компилятор JVM hкомпилирует код, надо запустить приложение с флагом
-XX:+PrintCompilation
Через определенный промежуток времени в консоли вы увидите что-то примерно такое:
139 1 3 java.lang.String::charAt (25 bytes)
140 2 3 java.lang.StringLatin1::charAt (28 bytes)
184 4 3 java.lang.Object::<init> (1 bytes)
184 6 3 java.lang.StringLatin1::hashCode (42 bytes)
185 5 3 java.lang.String::isLatin1 (19 bytes)
185 3 3 java.lang.String::hashCode (60 bytes)
185 7 3 java.util.ImmutableCollections$SetN::probe (56 bytes)
186 8 3 java.lang.Math::floorMod (20 bytes)
186 10 3 java.util.ImmutableCollections$SetN::hashCode (46 bytes)
186 9 3 java.lang.String::equals (50 bytes)
186 11 3 java.util.Objects::equals (23 bytes)
Эти строки говорят, какой метод какого класса был обработан JIT-компилятором.
Когда код хорошо прогрет, т.е. весь «горячий код» обработан JIT-компилятором и превращен в машинный нативный код, эти строки перестают появляться в консоли. Это служит хорошим сигналом, что ваше приложение достигло «нирваны» и работает на полной скорости.
Подробный лог компиляции
Если требуется более подробный лог процесса компиляции, вам поможет флаг
-XX:+UnlockDiagnosticVMOptions -XX:+LogCompilation
Этот флаг — диагностический и для его включения требуется дополнительный флаг -XX:+UnlockDiagnosticVMOptions. При запуске приложения с этим флагом, логи компиляции будут писаться в лог-файл, который по умолчанию будет называться
hotspot_pidNNNNNN.log
где NNNNNN — это цифры идентификатора Java-процесса. Название лог-файла можно указать в дополнительном параметре:
-XX:LogFile=foo.logЛог-файл компиляции представляет собой XML-файл весьма внушительного размера, который лучше всего смотреть с помощью специальной утилиты JITWatch, которую я упоминаю в отдельной статье.
PrintInlining
Еще один флаг, позволяющий проследить оптимизации, выполняемые компилятором, называется
-XX:+UnlockDiagnosticVMOptions -XX:+PrintInlining
При запуске приложения с этим флагом вы увидите в консоли примерно следующее:
@ 1 java.lang.String::isLatin1 (19 bytes) inline @ 12 java.lang.StringLatin1::charAt (28 bytes) inline @ 15 java/lang/StringIndexOutOfBoundsException::<init> (not loaded) not inlineable@ 21 java.lang.StringUTF16::charAt (11 bytes) inline @ 2 java.lang.StringUTF16::checkIndex (9 bytes) inline @ 2 java.lang.StringUTF16::length (5 bytes) inline @ 5 java.lang.String::checkIndex (48 bytes) callee is too large @ 7 java.lang.StringUTF16::getChar (60 bytes) intrinsic @ 17 java.lang.String::isLatin1 (19 bytes) inline
Это записи о том, какие методы компилятор заинлайнил, а какие — нет. Как вы заметили, не вес методы были заинлайнены. Некоторые методы оказались для компилятора слишком большими и он их игнорирует. Вы можете задать компилятору максимальный размер метода, который он должен инлайнить флагами:
-XX:C1MaxInlineSize=900 -XX:MaxInlineSize=900
где число — это размер в байтах. В данном примере я задал макс. размер метода для инлайнинга — 900 байт для компилятора C1 и для компилятора C2.
Машинный код
Еще один диагностический флаг
-XX:+UnlockDiagnosticVMOptions -XX:+PrintAssembly
позволяет увидеть машинный код, генерируемый JIT-компилятором.
Флаг PrintAssembly был добавлен в Java 6. Версии Java до 6-й его не узнают и не признают. Для распечатки машинного кода требовалась библиотека hsdis. Начиная с Java 9 кое-какой код выводится без hsdis, но вывод сопровождается строкой:
Could not load hsdis-amd64.dll; library not loadable; PrintAssembly is disabled
При запуске приложения с этим флагом в консоли вы увидите нечто такое:
============================= C2-compiled nmethod ==============================
----------------------------------- Assembly -----------------------------------
Compiled method (c2) 574 45 % 4 Demo::main @ 10 (40 bytes)
total in heap [0x0000027787ad4190,0x0000027787ad45b0] = 1056
relocation [0x0000027787ad42f0,0x0000027787ad4320] = 48
main code [0x0000027787ad4320,0x0000027787ad4400] = 224
stub code [0x0000027787ad4400,0x0000027787ad4438] = 56
oops [0x0000027787ad4438,0x0000027787ad4440] = 8
metadata [0x0000027787ad4440,0x0000027787ad4458] = 24
scopes data [0x0000027787ad4458,0x0000027787ad44b8] = 96
scopes pcs [0x0000027787ad44b8,0x0000027787ad4568] = 176
dependencies [0x0000027787ad4568,0x0000027787ad4570] = 8
handler table [0x0000027787ad4570,0x0000027787ad45a0] = 48
nul chk table [0x0000027787ad45a0,0x0000027787ad45b0] = 16
[Constant Pool (empty)]
[MachCode]
[Verified Entry Point]
# {method} {0x00000277fed30398} 'main' '([Ljava/lang/String;)V' in 'Demo'
0x0000027787ad4320: cc66 6666 | 0f1f 8400 | 0000 0000 | 6666 6690 | 8984 2400 | 90ff ff55 | 4883 ec40 | 488b 6a08
0x0000027787ad4340: 448b 2a48 | 8bca 49ba | 607f 2915 | fe7f 0000 | 41ff d244 | 8b5d 0866 | 0f1f 8400 | 0000 0000
0x0000027787ad4360: ; {metadata('java/util/ArrayList')}
0x0000027787ad4360: 4181 fbf2 | be01 000f | 8547 0000 | 0048 896c | 2420 418b | edeb 2366 | 0f1f 8400
0x0000027787ad437c: ;*iload_2 {reexecute=0 rethrow=0 return_oop=0}
; - Demo::main@10 (line 6)
Для нетренированного глаза эти строки выглядят как китайская грамота. -XX:+PrintAssembly распечатывает ВСЁ, но смотреть ВЕСЬ машинный код ВСЕХ методов ВСЕГО приложения не имеет большого смысла. Чтобы увидеть машинный код только критического участка, надо воспользоваться другим диагностическим флагом-параметром:
-XX:CompileCommand
Например, я хочу посмотреть машинный код метода addNumbers в моем классе Demo. Параметр запуска будет выглядеть так:
-XX:CompileCommand=print,Demo.addNumbers
Метод вызывается 1 миллион раз. Таким образом, его сначала его компилирует компилятор C1, а затем — компилятор C2. В результате в консоли я увижу:
CompileCommand: print Demo.addNumbers
============================= C1-compiled nmethod ==============================
----------------------------------- Assembly -----------------------------------
Compiled method (c1) 65 73 3 Demo::addNumbers (6 bytes)
total in heap [0x000001c3ec2e9b10,0x000001c3ec2e9de8] = 728
relocation [0x000001c3ec2e9c70,0x000001c3ec2e9c98] = 40
main code [0x000001c3ec2e9ca0,0x000001c3ec2e9d40] = 160
stub code [0x000001c3ec2e9d40,0x000001c3ec2e9d78] = 56
oops [0x000001c3ec2e9d78,0x000001c3ec2e9d80] = 8
metadata [0x000001c3ec2e9d80,0x000001c3ec2e9d88] = 8
scopes data [0x000001c3ec2e9d88,0x000001c3ec2e9da0] = 24
scopes pcs [0x000001c3ec2e9da0,0x000001c3ec2e9de0] = 64
dependencies [0x000001c3ec2e9de0,0x000001c3ec2e9de8] = 8
[Constant Pool (empty)]
[MachCode]
[Verified Entry Point]
# {method} {0x000001c3fee30480} 'addNumbers' '(II)I' in 'Demo'
# parm0: rdx = int
# parm1: r8 = int
# [sp+0x40] (sp of caller)
0x000001c3ec2e9ca0: 8984 2400 | 90ff ff55 | 4883 ec30
0x000001c3ec2e9cac: ; {metadata(method data for {method} {0x000001c3fee30480} 'addNumbers' '(II)I' in 'Demo')}
0x000001c3ec2e9cac: 48b8 5006 | e3fe c301 | 0000 8bb0 | 0401 0000 | 83c6 0289 | b004 0100 | 0081 e6fe | 0700 0083
0x000001c3ec2e9ccc: fe00 0f84
0x000001c3ec2e9cd0: ;*iload_0 {reexecute=0 rethrow=0 return_oop=0}
; - Demo::addNumbers@0 (line 15)
0x000001c3ec2e9cd0: 1600 0000 | 4103 d048 | 8bc2 4883 | c430 5d4d | 8b97 1001
0x000001c3ec2e9ce4: ; {poll_return}
0x000001c3ec2e9ce4: 0000 4185
0x000001c3ec2e9ce8: ; {metadata({method} {0x000001c3fee30480} 'addNumbers' '(II)I' in 'Demo')}
0x000001c3ec2e9ce8: 02c3 49ba | 7804 e3fe | c301 0000 | 4c89 5424 | 0848 c704 | 24ff ffff
0x000001c3ec2e9d00: ; {runtime_call counter_overflow Runtime1 stub}
0x000001c3ec2e9d00: ffe8 7a5e
0x000001c3ec2e9d04: ; ImmutableOopMap {}
;*synchronization entry
; - Demo::addNumbers@-1 (line 15)
0x000001c3ec2e9d04: b4ff ebcc | 9090 498b | 8700 0400 | 0049 ba00 | 0000 0000 | 0000 004d | 8997 0004 | 0000 49ba
0x000001c3ec2e9d24: 0000 0000 | 0000 0000 | 4d89 9708 | 0400 0048 | 83c4 305d
0x000001c3ec2e9d38: ; {runtime_call unwind_exception Runtime1 stub}
0x000001c3ec2e9d38: e943 f5b3 | fff4 f4f4
[Exception Handler]
0x000001c3ec2e9d40: ; {no_reloc}
0x000001c3ec2e9d40: e83b 28b4
0x000001c3ec2e9d44: ; {external_word}
0x000001c3ec2e9d44: ff48 b9e0 | eaa5 15fe | 7f00 0048
0x000001c3ec2e9d50: ; {runtime_call}
0x000001c3ec2e9d50: 83e4 f049 | baa0 ae76 | 15fe 7f00 | 0041 ffd2
0x000001c3ec2e9d60: ; {section_word}
0x000001c3ec2e9d60: f449 ba61 | 9d2e ecc3 | 0100 0041
0x000001c3ec2e9d6c: ; {runtime_call DeoptimizationBlob}
0x000001c3ec2e9d6c: 52e9 2e42 | a9ff f4f4 | f4f4 f4f4
[/MachCode]
============================= C2-compiled nmethod ==============================
----------------------------------- Assembly -----------------------------------
Compiled method (c2) 70 80 4 Demo::addNumbers (6 bytes)
total in heap [0x000001c3f3805990,0x000001c3f3805bc0] = 560
relocation [0x000001c3f3805af0,0x000001c3f3805af8] = 8
main code [0x000001c3f3805b00,0x000001c3f3805b40] = 64
stub code [0x000001c3f3805b40,0x000001c3f3805b58] = 24
oops [0x000001c3f3805b58,0x000001c3f3805b60] = 8
metadata [0x000001c3f3805b60,0x000001c3f3805b68] = 8
scopes data [0x000001c3f3805b68,0x000001c3f3805b78] = 16
scopes pcs [0x000001c3f3805b78,0x000001c3f3805bb8] = 64
dependencies [0x000001c3f3805bb8,0x000001c3f3805bc0] = 8
[Constant Pool (empty)]
[MachCode]
[Verified Entry Point]
# {method} {0x000001c3fee30480} 'addNumbers' '(II)I' in 'Demo'
# parm0: rdx = int
# parm1: r8 = int
# [sp+0x20] (sp of caller)
0x000001c3f3805b00: 4881 ec18 | 0000 0048
0x000001c3f3805b08: ;*synchronization entry
; - Demo::addNumbers@-1 (line 15)
0x000001c3f3805b08: 896c 2410 | 8bc2 4103
0x000001c3f3805b10: ;*iadd {reexecute=0 rethrow=0 return_oop=0}
; - Demo::addNumbers@2 (line 15)
0x000001c3f3805b10: c048 83c4 | 105d 4d8b | 9710 0100
0x000001c3f3805b1c: ; {poll_return}
0x000001c3f3805b1c: 0041 8502 | c3f4 f4f4 | f4f4 f4f4 | f4f4 f4f4 | f4f4 f4f4 | f4f4 f4f4 | f4f4 f4f4 | f4f4 f4f4
0x000001c3f3805b3c: f4f4 f4f4
[Exception Handler]
0x000001c3f3805b40: ; {no_reloc}
0x000001c3f3805b40: e93b 3d62 | f8e8 0000 | 0000 4883
0x000001c3f3805b4c: ; {runtime_call DeoptimizationBlob}
0x000001c3f3805b4c: 2c24 05e9 | 4c84 57f8 | f4f4 f4f4
[/MachCode]
Я запускал свое приложение на JDK 15 на Intel Core i-5-6400T. У вас машинный код может получиться другой.
Ассемблерный код
Все равно, выдаваемый результат не имеет никакого смысла. Ведь все, что мы видим на экране это hex-коды машинного кода с адресами памяти. Для того, чтобы преобразовать их в ассемблерные инструкции, требуется дополнительная библиотека hsdis. Эта библиотека поставляется в исходниках jdk. Она не распространяется отдельно. Ее можно собрать самостоятельно для windows или для linux. Если поместить эту библиотеку в bin папку jdk, и запустить программу с вышеуказанными параметрами, на экране выведется полноценный читаемый ассемблерный код с комментариями. Например,
0x0000025ed5024723: mov rcx,QWORD PTR [r15+0x348] ; ImmutableOopMap {rdi=Oop }
;*if_icmplt {reexecute=1 rethrow=0 return_oop=0}
; - (reexecute) Main::intStride1@22 (line 19)
0x0000025ed502472a: test DWORD PTR [rcx],eax ; {poll}
0x0000025ed502472c: cmp ebx,r11d
0x0000025ed502472f: jge 0x0000025ed5024786
0x0000025ed5024735: mov ecx,r11d
0x0000025ed5024738: sub ecx,ebx
0x0000025ed502473a: cmp r11d,ebx
0x0000025ed502473d: cmovl ecx,r8d
0x0000025ed5024741: cmp ecx,0x1f40
0x0000025ed5024747: cmova ecx,r9d
0x0000025ed502474b: add ecx,ebx
0x0000025ed502474d: data16 xchg ax,ax
0x0000025ed5024750: add r12,QWORD PTR [rdi+rbx*8+0x10]
0x0000025ed5024755: movsxd rdx,ebx
0x0000025ed5024758: add r12,QWORD PTR [rdi+rdx*8+0x18]
0x0000025ed502475d: add r12,QWORD PTR [rdi+rdx*8+0x20]
0x0000025ed5024762: add r12,QWORD PTR [rdi+rdx*8+0x28]
0x0000025ed5024767: add r12,QWORD PTR [rdi+rdx*8+0x30]
0x0000025ed502476c: add r12,QWORD PTR [rdi+rdx*8+0x38]
0x0000025ed5024771: add r12,QWORD PTR [rdi+rdx*8+0x40]
0x0000025ed5024776: add r12,QWORD PTR [rdi+rdx*8+0x48]
0x0000025ed502477b: add ebx,0x8
0x0000025ed502477e: xchg ax,ax
0x0000025ed5024780: cmp ebx,ecx
0x0000025ed5024782: jl 0x0000025ed5024750
0x0000025ed5024784: jmp 0x0000025ed5024723
0x0000025ed5024786: cmp ebx,r10d
0x0000025ed5024789: jge 0x0000025ed5024798
0x0000025ed502478b: nop
0x0000025ed502478c: add r12,QWORD PTR [rdi+rbx*8+0x10]
0x0000025ed5024791: inc ebx
0x0000025ed5024793: cmp ebx,r10d
0x0000025ed5024796: jl 0x0000025ed502478c
0x0000025ed5024798: mov edx,0xffffff45
0x0000025ed502479d: mov rbp,r12
0x0000025ed50247a0: mov DWORD PTR [rsp+0x24],ebx
0x0000025ed50247a4: mov DWORD PTR [rsp+0x28],r10d
Этот листинг уже может прочитать человек, и выяснить, что именно сделал JIT компилятор. Это пригодится для отладки какого-то критического участка вашего приложения, где вы точно хотите быть уверены, что генерируемый код соответствует вашим ожиданиям.
Кэш скопилированного кода
Код, который генерируют компиляторы C1 и C2 во время своей работы кэширется во внутренней структуре JVM, которая называется CodeCache.
Кэш имеет определенный размер. Посмотреть размеры кэша по умолчанию и другие параметры связанные с эшем можно запустив приложение с флагом -XX:+PrintFlagsFinal и отфильтровав строки по подстроке CodeCache.
По мере работы приложения и «прогрева кода» CodeCache заполняется, и в конце концов в кэше может не остаться места. В этом случае JVM сбрасывает ненужный код и на освободившееся место записывает новый. Этот процесс называется CodeCacheFlushing. Эта информация важна для достижения low-latency:
- На сброс кода требуется время, что может вызвать задержки
- Сброшенный «старый код» может оказаться важным для какой-то задачи через несколько минут. В этом случае ваш код будет исполняться в режиме интерпретации, т.е. значительно медленнее, чем хотелось бы. А после какого-то времени JIT-компилятор начнет компилировать этот участок кода, а потом снова замещать интерпретированный участок на компилированный. На это тоже уйдет время и может вызвать нежелательные задержки при работе программы.
Поэтому в приложениях, где latency критично, рекомендуется отключать сброс кэша кода с помощью флага -XX:-UseCodeCacheFlushing. В этом случае, все что накомпилируют компиляторы C1 и C2 навечно останется в кэше. Если место к кэше кончится и свободного места для нового кода не будет, компиляция прекратится и оставшийся неоткомпиллированный код будет исполняться в режиме интерпретации. Чтобы этого не произошло, выставляйте размер кэша кода как можно большим, подбирая оптимальный размер экспериментальным путем с помощью флагов -XX:InitialCodeCacheSize и -XX:ReservedCodeCacheSize.
Начиная с Java 8 в JVM включена ступенчатая, поэтапная компиляция (tiered compilation). Если она включена, область памяти под кэш кода должна быть по-больше. Если ступенчатая компиляция отключена — по-меньше. Изменение размера делается автоматически в JVM, если размер кэша не выставлен явно с помощью параметров.
Посмотреть на размер и использование кэша можно с помощью этих флагов:
- -XX:+PrintCodeCache — распечатает общую информацию о кэше кода при завершении работы приложения
- -XX:+PrintCodeCacheOnCompilation — будет выводить информацию о состоянии кэша кода при каждой компиляции
Ссылки
Algo & DMA: технологии биржевой торговли 