Как посмотреть, что и как компилирует JIT-компилятор?

В данной статье я кратко описываю диагностические флаги 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 — будет выводить информацию о состоянии кэша кода при каждой компиляции

Ссылки

Добавить комментарий

Заполните поля или щелкните по значку, чтобы оставить свой комментарий:

Логотип WordPress.com

Для комментария используется ваша учётная запись WordPress.com. Выход /  Изменить )

Фотография Twitter

Для комментария используется ваша учётная запись Twitter. Выход /  Изменить )

Фотография Facebook

Для комментария используется ваша учётная запись Facebook. Выход /  Изменить )

Connecting to %s