Upgrade to Pro — share decks privately, control downloads, hide ads and more …

How to implement an internal JVM profiler that ...

How to implement an internal JVM profiler that works well with AOT-compiled code? (JPoint 2018)

The number of ways to profile Java code is vast, and so is the number of profilers which allow doing that. Not so long time ago we had to build the profile for applications which run on Excelsior JET. It was to be done on all maintained systems and architectures, without app recompilation, and all this with satisfactory performance. It turned out that traditional ways of profiling do not work here, so we had to think of something of our own.

In this talk, we’ll discuss:

- why JVM and AOT were in need of a built-in profiler;
- the ways to profile Java code and how they work for AOT compilation;
- the options while profiling the code from within the JVM;
- the price we had to pay for the universal profiler we got.

Ivan Ugliansky

April 06, 2018
Tweet

More Decks by Ivan Ugliansky

Other Decks in Programming

Transcript

  1. ➢ 6 лет в Excelsior ➢ JVM инженер в проекте

    Excelsior JET ◦ разрабатываю рантайм 2 Иван Углянский [email protected] @dbg_nsk
  2. JIT: ✓ получение профиля исполнения ✓ перекомпиляция горячих методов ✓

    деоптимизации при необходимости ✓ эффективен на профиле с явными пиками 9 JIT vs AOT
  3. AOT: ✓ only one shot ✓ но ресурсов для оптимизаций

    больше ✓ эффективен на плоском профиле 14 JIT vs AOT
  4. 24 1. Информативность 2. Универсальность Требования: ➢ Горячие методы +

    call chains ➢ Windows/macOS/Linux + x86/AMD64/ARM32 Profile-Guided Optimization
  5. 25 1. Информативность 2. Универсальность 3. Простота Требования: ➢ Горячие

    методы + call chains ➢ Windows/macOS/Linux + x86/AMD64/ARM32 ➢ Включать профилировку VM опцией Profile-Guided Optimization
  6. 26 1. Информативность 2. Универсальность 3. Простота 4. Эффективность Требования:

    ➢ Горячие методы + call chains ➢ Windows/macOS/Linux + x86/AMD64/ARM32 ➢ Включать профилировку VM опцией ➢ Промышленное использование Profile-Guided Optimization
  7. 27 1. Информативность 2. Универсальность 3. Простота 4. Эффективность Требования:

    ➢ Горячие методы + call chains ➢ Windows/macOS/Linux + x86/AMD64/ARM32 ➢ Включать профилировку VM опцией ➢ Промышленное использование Profile-Guided Optimization
  8. 31 В код добавляется учет статистики (циклы, методы, типы) Точная*

    информация о профиле Инструментировать можно: ◦ Java bytecode ◦ Native code Instrumentation
  9. 32 public class Test { ... public static int testMethod(int

    counts, int val) { int res = 0; for (int i = 0; i < counts; i++) { res += val; } return res; } ... } $ java -XX:+UnlockDiagnosticVMOptions -XX:+PrintAssembly Test Instrumentation
  10. 33 # {method} {0x0000000016930308} 'testMethod' '(II)I' in 'Test' # parm0:

    rdx = int # parm1: r8 = int # [sp+0x40] (sp of caller) 0x0000000002683b80: mov DWORD PTR [rsp-0x6000],eax 0x0000000002683b87: push rbp 0x0000000002683b88: sub rsp,0x30 0x0000000002683b8c: movabs rax,0x16930560 ; {metadata(method data for {method} ... 'testMethod' ...} 0x0000000002683b96: mov esi,DWORD PTR [rax+0xdc] 0x0000000002683b9c: add esi,0x8 0x0000000002683b9f: mov DWORD PTR [rax+0xdc],esi 0x0000000002683ba5: movabs rax,0x16930300 ; {metadata({method} ... 'testMethod' ... } ... Instrumentation
  11. 34 # {method} {0x0000000016930308} 'testMethod' '(II)I' in 'Test' # parm0:

    rdx = int # parm1: r8 = int # [sp+0x40] (sp of caller) 0x0000000002683b80: mov DWORD PTR [rsp-0x6000],eax 0x0000000002683b87: push rbp 0x0000000002683b88: sub rsp,0x30 0x0000000002683b8c: movabs rax,0x16930560 ; {metadata(method data for {method} ... 'testMethod' ...} 0x0000000002683b96: mov esi,DWORD PTR [rax+0xdc] 0x0000000002683b9c: add esi,0x8 0x0000000002683b9f: mov DWORD PTR [rax+0xdc],esi 0x0000000002683ba5: movabs rax,0x16930300 ; {metadata({method} ... 'testMethod' ... } ... HotSpot C1 Compiler инкремент счетчика Instrumentation
  12. 35 Интерпретатор C1: без профилировки C1: частичная профилировка C1: полная

    профилировка С2 0 1 2 3 4 Уровни компиляции Instrumentation
  13. 36 Интерпретатор C1: без профилировки C1: частичная профилировка C1: полная

    профилировка С2 0 1 2 3 4 Уровни компиляции Instrumentation
  14. 38 Почему нам в AOT не подходит инструментация? ➢ Отдельный

    режим сборки для профилирования ➢ Инструментация каждого метода ⇒ ➢ Плохая производительность Instrumentation
  15. 39 1. Информативность 2. Универсальность 3. Простота 4. Эффективность ➢

    Горячие методы + call chains ➢ Windows/macOS/Linux + x86/AMD64/ARM32 ➢ Включать профилировку VM опцией ➢ Промышленное использование Требования: Instrumentation
  16. 41 Интерпретатор C1: без профилировки C1: частичная профилировка C1: полная

    профилировка С2 0 1 2 3 4 Уровни компиляции Instrumentation
  17. 42 Интерпретатор C1: без профилировки C1: частичная профилировка C1: полная

    профилировка С2 0 1 2 3 4 Уровни компиляции HotSpot AOT: профилировка Instrumentation
  18. 44 Инструментация в HotSpot AOT: ◦ Обычная и вероятностная профилировка

    ◦ Вероятностная: ➢ борьба с cache line ping-ponging Instrumentation
  19. 45 Инструментация в HotSpot AOT: ◦ Обычная и вероятностная профилировка

    ◦ Вероятностная: ➢ борьба с cache line ping-ponging ➢ счетчики срабатывают не каждый раз ➢ if (random() & ((1 << prob_log) - 1) == 0) {...} Instrumentation
  20. 46 Инструментация в HotSpot AOT: ◦ Обычная и вероятностная профилировка

    ◦ Вероятностная: ➢ борьба с cache line ping-ponging ➢ счетчики срабатывают не каждый раз ➢ if (random() & ((1 << prob_log) - 1) == 0) {...} Instrumentation
  21. 47 1. Информативность 2. Универсальность 3. Простота 4. Эффективность ➢

    Горячие методы + call chains ➢ Windows/macOS/Linux + x86/AMD64/ARM32 ➢ Включать профилировку VM опцией ➢ Промышленное использование Требования: Instrumentation
  22. 49 Раз в заданный промежуток времени проводится инспекция Качество профиля

    зависит от интервала семплирования, меньше — лучше Sampling
  23. 51 Safepoints ➢ Точки в коде, где доступен стек вызовов

    ➢ В них можно приостановить потоки
  24. 52 ➢ Точки в коде, где доступен стек вызовов ➢

    В них можно приостановить потоки ➢ Достигаются (относительно) быстро ➢ Ухудшают производительность Safepoints
  25. 53 public class Test { . . . public static

    int test(int limit, int step) { int res = 0; while (res < limit) { res += step; } return res; } . . . } $ java -XX:-TieredCompilation -XX:+UnlockDiagnosticVMOptions -XX:+PrintAssembly Test Safepoints
  26. 54 ... 0x000001dcb19ce3e0: add eax,r9d 0x000001dcb19ce3e3: test DWORD PTR [rip+0xfffffffff3d41c17],eax

    ; {poll} 0x000001dcb19ce3e9: cmp eax,r8d 0x000001dcb19ce3ec: jl 0x000001dcb19ce3e0 0x000001dcb19ce3ee: add rsp,0x10 0x000001dcb19ce3f2: pop rbp 0x000001dcb19ce3f3: test DWORD PTR [rip+0xfffffffff3d41c07],eax ; {poll_return} 0x000001dcb19ce3f9: ret ... Safepoints
  27. 55 ... 0x000001dcb19ce3e0: add eax,r9d 0x000001dcb19ce3e3: test DWORD PTR [rip+0xfffffffff3d41c17],eax

    ; {poll} 0x000001dcb19ce3e9: cmp eax,r8d 0x000001dcb19ce3ec: jl 0x000001dcb19ce3e0 0x000001dcb19ce3ee: add rsp,0x10 0x000001dcb19ce3f2: pop rbp 0x000001dcb19ce3f3: test DWORD PTR [rip+0xfffffffff3d41c07],eax ; {poll_return} 0x000001dcb19ce3f9: ret ... Safepoints
  28. 56 Safepoints based profilers: ➢ «Включают» остановку на safepoints ➢

    Ждут, пока потоки достигнут sp ➢ Собирают стеки вызовов ➢ «Выключают» остановку на safepoints Safepoints
  29. 59 public class Test2 { ... public int testMethod(int value)

    { int res = 0; for (int i = 0; i < 100000; i++) { res += value; } witness(); return res; } ... } $ java -XX:-TieredCompilation -XX:+UnlockDiagnosticVMOptions -XX:+PrintAssembly Test2 Safepoints
  30. 60 ... 0x000001bef9d3e30c: add ebp,r8d 0x000001bef9d3e30f: inc r10d 0x000001bef9d3e312: cmp

    r10d,0x2710 0x000001bef9d3e319: jl 0x000001bef9d3e30c 0x000001bef9d3e31b: call 0x000001bef9d3e340 0x000001bef9d3e320: mov eax,ebp 0x000001bef9d3e322: add rsp,0x10 0x000001bef9d3e326: pop rbp 0x000001bef9d3e327: test DWORD PTR [rip+0xfffffffffe521cd3],eax ; {poll_return} 0x000001bef9d3e32d: ret ... Safepoints
  31. 61 ... 0x000001bef9d3e30c: add ebp,r8d 0x000001bef9d3e30f: inc r10d 0x000001bef9d3e312: cmp

    r10d,0x2710 0x000001bef9d3e319: jl 0x000001bef9d3e30c 0x000001bef9d3e31b: call 0x000001bef9d3e340 0x000001bef9d3e320: mov eax,ebp 0x000001bef9d3e322: add rsp,0x10 0x000001bef9d3e326: pop rbp 0x000001bef9d3e327: test DWORD PTR [rip+0xfffffffffe521cd3],eax ; {poll_return} 0x000001bef9d3e32d: ret ... No polls! Safepoints
  32. 62 public class Test2 { ... public int testMethod(int value)

    { int res = 0; for (int i = 0; i < 100000; i++) { res += value; } witness(); return res; } ... } Слепая зона Попадет в профиль (вместо testMethod) Safepoints
  33. 63 Почему нам не подходит семплирование через safe points? 1.

    Слепые зоны 2. Непредсказуемое время инспекций Safepoints
  34. 64 Почему нам не подходит семплирование через safe points? 1.

    Слепые зоны 2. Непредсказуемое время инспекций Why (Most) Sampling Java Profilers Are F*cking Terrible by Nitsan Wakart Safepoints
  35. 65 1. Информативность 2. Универсальность 3. Простота 4. Эффективность ➢

    Горячие методы + call chains ➢ Windows/macOS/Linux + x86/AMD64/ARM32 ➢ Включать профилировку VM опцией ➢ Промышленное использование Требования: Safepoints
  36. 69 ➢ OpenJDK internal API ➢ Posix Signals, SIGPROF ➢

    В обработчике вызов AsyncGetCallTrace AsyncGetCallTrace
  37. 70 ➢ OpenJDK internal API ➢ Posix Signals, SIGPROF ➢

    В обработчике вызов AsyncGetCallTrace ➢ Стек вызовов ВНЕ safepoint AsyncGetCallTrace
  38. 71 ➢ OpenJDK internal API ➢ Posix Signals, SIGPROF ➢

    В обработчике вызов AsyncGetCallTrace ➢ Стек вызовов ВНЕ safepoint ➢ Честность ➢ Не зависит от количества потоков AsyncGetCallTrace
  39. 72 Ложка дегтя enum { ticks_no_Java_frame = 0, // new

    thread ticks_no_class_load = -1, // jmethodIds are not available ticks_GC_active = -2, // GC action ticks_unknown_not_Java = -3, // ¯\_(ツ)_/¯ ticks_not_walkable_not_Java = -4, // ¯\_(ツ)_/¯ ticks_unknown_Java = -5, // ¯\_(ツ)_/¯ ticks_not_walkable_Java = -6, // ¯\_(ツ)_/¯ ticks_unknown_state = -7, // ¯\_(ツ)_/¯ ticks_thread_exit = -8, // dying thread ticks_deopt = -9, // mid-deopting code ticks_safepoint = -10 // ¯\_(ツ)_/¯ }; AsyncGetCallTrace
  40. 74 1. Информативность 2. Универсальность 3. Простота 4. Эффективность Требования:

    ➢ Горячие методы + call chains ➢ Windows/macOS/Linux + x86/AMD64/ARM32 ➢ Включать профилировку VM опцией ➢ Промышленное использование AsyncGetCallTrace
  41. 78 WinBase.SuspendThread(HANDLE) pthread_kill(pthread_t, int) Профилировщик в Excelsior JET Posix Signals

    Остановка потока в произвольной точке Prying Profiler
  42. 82 Схема работы: 1. Отдельный поток для профилировщика 2. Инспекции

    раз в заданный интервал a. Останавливаем очередной поток системными средствами b. Восстанавливаем стек вызовов для потока (не только в safepoint) c. Возобновляем работу потока Prying Profiler
  43. 84 ... return address return address ... SP Фрейм Bar

    Фрейм Foo ◦ Foo вызывает Bar ◦ Инспектируем поток Как получить стек вызовов в произвольной точке? Prying Profiler
  44. 85 ... return address return address ... SP Фрейм Bar

    Фрейм Foo ◦ Foo вызывает Bar ◦ Инспектируем поток Как получить стек вызовов в произвольной точке? 1. По IP находим Bar 2. Осталось найти фрейм Foo Prying Profiler
  45. 86 testMethod: push rbx push rbp add rsp, byte -8

    mov eax, dword [rsp-0C00H] lea rax, [rel L004] ... xor eax, eax jmp short L022 ; v L021: mov r9, qword [r15+1D0H] mov r9d, dword [r9] add eax, r8d L022: cmp edx, eax jg L021 ; ^ ... L023: add rsp, byte 8 pop rbp pop rbx mov rcx, qword [r15+1E0H] mov ecx, dword [rcx] ret Пролог Эпилог Тело метода Prying Profiler
  46. 87 testMethod: push rbx push rbp add rsp, byte -8

    mov eax, dword [rsp-0C00H] lea rax, [rel L004] ... xor eax, eax jmp short L022 ; v L021: mov r9, qword [r15+1D0H] mov r9d, dword [r9] add eax, r8d L022: cmp edx, eax jg L021 ; ^ ... L023: add rsp, byte 8 pop rbp pop rbx mov rcx, qword [r15+1E0H] mov ecx, dword [rcx] ret Исполняли тело метода ⇒ фрейм сформирован (почти safepoint) Prying Profiler
  47. 88 testMethod: push rbx push rbp add rsp, byte -8

    mov eax, dword [rsp-0C00H] lea rax, [rel L004] ... xor eax, eax jmp short L022 ; v L021: mov r9, qword [r15+1D0H] mov r9d, dword [r9] add eax, r8d L022: cmp edx, eax jg L021 ; ^ ... L023: add rsp, byte 8 pop rbp pop rbx mov rcx, qword [r15+1E0H] mov ecx, dword [rcx] ret Исполняли пролог или эпилог ⇒ фрейма еще (уже) нет Знаем, как искать caller фрейм Prying Profiler
  48. 89 public int lightweightMethod(int p) { int res = 1;

    for (int i = 0; i < 100; i++) { res *= p; } return res; } Особый метод: ◦ Исключений не бросает ◦ Safepoints в теле нет ◦ Call stack не сканируется Prying Profiler
  49. 90 lightweightMethod: mov eax, 1 xor ecx, ecx jmp short

    L018 ; v L017: imul eax, edx add ecx, byte 1 L018: cmp ecx, byte 100 jl L017 ; ^ mov rcx, qword [r15+1E0H] mov ecx, dword [rcx] ret Оптимизация: фрейм вообще не строится (никто ведь не будет сканировать call stack) Prying Profiler
  50. 91 Худший случай: ◦ Достоверной информации о caller фрейме нет

    ◦ Используются эвристики (ищем ближайший хороший фрейм) ◦ Редкий случай, умеем отличать в профиле lightweightMethod: mov eax, 1 xor ecx, ecx jmp short L018 ; v L017: imul eax, edx add ecx, byte 1 L018: cmp ecx, byte 100 jl L017 ; ^ mov rcx, qword [r15+1E0H] mov ecx, dword [rcx] ret Prying Profiler
  51. 92 Что попадает в профиль? ➢ Java методы попадают в

    профиль ◦ точные или эвристические хиты ➢ Native методы распознаются, но игнорируются ➢ Часть потоков отфильтровываются ◦ служебные потоки JVM ◦ потоки исполняющие OS Prying Profiler
  52. 93 интервал между инспекциями — 1ms издержки производительности — ~10%

    достаточная информативность и точность Prying Profiler
  53. 94 Intel® VTune™ Amplifier Method name CPU Time Collections.longStaticBTree.getObject 12.5662%

    Util.DisplayScreen.putText 4.3703% Collections.StringBTreeNode.SearchNode 2.5284% Util.DisplayScreen.putDollars 2.5115% StockLevelTransaction.process 2.4576% Prying Profiler
  54. 95 Intel® VTune™ Amplifier Method name CPU Time Collections.longStaticBTree.getObject 12.5662%

    Util.DisplayScreen.putText 4.3703% Collections.StringBTreeNode.SearchNode 2.5284% Util.DisplayScreen.putDollars 2.5115% StockLevelTransaction.process 2.4576% Excelsior JET Prying Profiler Method name Hits Collections.longStaticBTree.getObject 14.659% Util.DisplayScreen.putText 4.690% Util.DisplayScreen.putDollars 3.029% Collections.StringBTreeNode.SearchNode 3.013% StockLevelTransaction.process 2.713% Prying Profiler
  55. 96 интервал между инспекциями — 1ms издержки производительности — ~10%

    достаточная информативность и точность Prying Profiler
  56. 97 интервал между инспекциями — 1ms (варьируется) издержки производительности —

    ~10% (есть контрпримеры) достаточная информативность и точность Prying Profiler
  57. 98 1. Информативность 2. Универсальность 3. Простота 4. Эффективность ➢

    Горячие методы + call chains ➢ Windows/macOS/Linux + x86/AMD64/ARM32 ➢ Включать профилировку VM опцией ➢ Промышленное использование Требования: Prying Profiler
  58. 99 1. Информативность 2. Универсальность 3. Простота 4. Эффективность ➢

    Горячие методы + call chains ➢ Windows/macOS/Linux + x86/AMD64/ARM32 ➢ Включать профилировку VM опцией ➢ Промышленное использование Требования: Prying Profiler
  59. 100 1. Информативность 2. Универсальность 3. Простота 4. Эффективность ➢

    Горячие методы + call chains ➢ Windows/macOS/Linux + x86/AMD64/ARM32 ➢ Включать профилировку VM опцией ➢ Промышленное использование Требования: Prying Profiler
  60. 103 ➢ Hardware Counters ➢ Семплирование при переполнении ➕ Минимальные

    издержки ➕ Высокая частота семплирования Hardware Profiling
  61. 104 ➢ Hardware Counters ➢ Семплирование при переполнении ➕ Минимальные

    издержки ➕ Высокая частота семплирования ➖ CPU- и OS-специфично ➖ Privileged instructions Hardware Profiling
  62. 106 ➢ Linux Perf Events ◦ kernel 2.6.31 and above

    ➢ Clairvoyance Profiler Hardware Profiling
  63. 107 ➢ Linux Perf Events ◦ kernel 2.6.31 and above

    ➢ Clairvoyance Profiler ◦ perf_event_open Hardware Profiling
  64. 108 ➢ Linux Perf Events ◦ kernel 2.6.31 and above

    ➢ Clairvoyance Profiler ◦ perf_event_open ◦ CPU записывает семлы в ring buffer data_tail Hardware Profiling
  65. 109 ➢ Linux Perf Events ◦ kernel 2.6.31 and above

    ➢ Clairvoyance Profiler ◦ perf_event_open ◦ CPU записывает семлы в ring buffer PERF_RECORD_LOST++ data_tail Hardware Profiling
  66. 110 ➢ Linux Perf Events ◦ kernel 2.6.31 and above

    ➢ Clairvoyance Profiler ◦ perf_event_open ◦ CPU записывает семлы в ring buffer ◦ JVM обрабатывает буфер, обновляет data_tail data_tail data_tail обработанные семлпы JVM profiler thread Hardware Profiling
  67. 111 ➢ Linux Perf Events ◦ kernel 2.6.31 and above

    ➢ Clairvoyance Profiler ◦ perf_event_open ◦ CPU записывает семлы в ring buffer ◦ JVM обрабатывает буфер, обновляет data_tail ◦ издержки ~2% Hardware Profiling
  68. ➢ Clairvoyance Profiler ◦ perf_event_open ◦ CPU записывает семлы в

    ring buffer ◦ JVM обрабатывает буфер, обновляет data_tail ◦ издержки ~2% 112 Hardware Profiling
  69. 113 1. Информативность 2. Универсальность 3. Простота 4. Эффективность ➢

    Горячие методы + call chains ➢ Windows/macOS/Linux + x86/AMD64/ARM32 ➢ Включать профилировку VM опцией ➢ Промышленное использование Требования: Hardware Profiling
  70. 114 Но есть backup path ― Prying Profiler! 1. Информативность

    2. Универсальность 3. Простота 4. Эффективность ➢ Горячие методы + call chains ➢ Windows/macOS/Linux + x86/AMD64/ARM32 ➢ Включать профилировку VM опцией ➢ Промышленное использование Требования: Hardware Profiling
  71. 115 Заключение Сейчас: ➢ Prying Profiler включен в Excelsior JET

    ➢ PGO ➢ Отладка Потом: ➢ Clairvoyance Profiler ➢ Общедоступность профилировщика
  72. 118 ComplexTask Task ByteTask Byte4Task static void initData() { dataArr

    = new Task[DATA_SIZE]; Task t1 = new Byte4Task(); Task t2 = new ByteTask (); for (int i = 0; i < dataArr.length; i++) { dataArr[i] = (i % 64 == 0) ? t1 : t2; } } Demo
  73. 119 ComplexTask Task ByteTask Byte4Task static void initData() { dataArr

    = new Task[DATA_SIZE]; Task t1 = new Byte4Task(); Task t2 = new ByteTask (); for (int i = 0; i < dataArr.length; i++) { dataArr[i] = (i % 64 == 0) ? t1 : t2; } } ... for (Task t : dataArr) { res += t.compute(); } ... Demo
  74. 120 Результаты: OpenJDK 1.8.0_151-1b, Windows, x86_amd64 803 ms JET 14.0

    Windows-amd64 4 388 ms JET 14.0 Windows-amd64 + Profiler 4 811 ms JET 14.0 Windows-amd64 + PGO 525 ms Пример на github: https://github.com/excelsior-oss/excelsior-jet-samples/tree/master/pgo-bench Demo
  75. 122 Secret slide А что по поводу JMC/JFR? ➢ Видит

    между safepoints только с -XX:DebugNonSafepoints ➢ Минимальный интервал семплирования 10ms ➢ Универсальность (работает и на Windows)
  76. 123 Secret slide А что по поводу JMC/JFR? 1. Информативность

    2. Универсальность 3. Простота 4. Эффективность ➢ Горячие методы + call chains ➢ Windows/macOS/Linux + x86/AMD64/ARM32 ➢ Включать профилировку VM опцией ➢ Промышленное использование