Slide 1

Slide 1 text

Анонсы Диагностика JVM из командной строки Вебинар – 23 января https://training.ragozin.info/w20240123 Эффективное профилирование Java приложений Онлайн курс – 26-28 февраля 3 модуля * 3 занятия * 3 часа Промокод: JUGMSK (20 000 за первый модуль) https://training.ragozin.info/online

Slide 2

Slide 2 text

Анонсы Эффективное профилирование Java приложений Онлайн курс – 26-28 февраля Промокод: JUGMSK (20 000 за первый модуль) https://training.ragozin.info/online Модуль 1 Техники профилирования - от сэмплирования, до трассировки Модуль 2 Mission Control и Java Flight Recorder Удалённый доступ к JVM и архитектура JMX Модуль 3 Память JVM, анализ дампов Анализ много поточных приложений

Slide 3

Slide 3 text

SJK спешит на помощь! [email protected] Алексей Рагозин Москва, Январь 2024

Slide 4

Slide 4 text

SJK спешит на помощь! Консоль наше всё! Контейнеры и проклятие JMX перерыв Автоматизируем профилирование

Slide 5

Slide 5 text

Часть 1 Консоль наше всё!

Slide 6

Slide 6 text

Экосистема Java профайлеров “Настольные” инструменты - работают локально, либо надо настраивать JMX и доступ к сети Системы типа APM – требуют инфраструктуры и настройки Инструменты JDK – работают из терминала, но не дают того что хочется

Slide 7

Slide 7 text

Хьюстон у нас проблема Что-то пошло не так … Заходим по SSH на сервер. [appuser@server]# top

Slide 8

Slide 8 text

Что есть в OpenJDK? jps – список Java процессов jmap – дампы и гистограммы памяти jstack – дамп потоков jstat – некоторые метрики JVM jinfo – информация о параметрах JVM и system properties jcmd – one tool to rule them all! jhsdb – postmortem диагностика (Java 9 and above)

Slide 9

Slide 9 text

jcmd – убер тул OpenJDK Compiler.CodeHeap_Analytics Compiler.codecache Compiler.codelist Compiler.directives_add Compiler.directives_clear Compiler.directives_print Compiler.directives_remove Compiler.perfmap Compiler.queue GC.class_histogram GC.finalizer_info GC.heap_dump GC.heap_info GC.run GC.run_finalization JFR.check JFR.configure JFR.dump JFR.start JFR.stop JVMTI.agent_load JVMTI.data_dump ManagementAgent.start ManagementAgent.start_local ManagementAgent.status ManagementAgent.stop System.trim_native_heap Thread.print VM.cds VM.class_hierarchy VM.classloader_stats VM.classloaders VM.command_line VM.dynlibs VM.events VM.flags VM.info VM.log VM.metaspace VM.native_memory VM.print_touched_methods VM.set_flag VM.stringtable VM.symboltable VM.system_properties VM.systemdictionary VM.uptime VM.version

Slide 10

Slide 10 text

А что же я хочу увидеть? • Потребление CPU по потокам информация доступна в JMX начиная с Java 6! • Метрики GC скорость заполнения Eden статистику мертвых объектов

Slide 11

Slide 11 text

Mission Control Mission Control –мониторинг потоков

Slide 12

Slide 12 text

SJK – первые шаги ttop > java –jar sjk.jar ttop -p 12345 2016-11-07T00:09:50.091+0400 Process summary process cpu=268.35% application cpu=244.42% (user=222.50% sys=21.93%) other: cpu=23.93% GC time=6.28% (young=1.62%, old=4.66%) heap allocation rate 1218mb/s safe point rate: 1.5 (events/s) avg. safe point pause: 43.24ms safe point sync time: 0.03% processing time: 6.39% (wallclock time) [000056] user=17.45% sys= 0.62% alloc= 106mb/s - hz._hzInstance_2_dev.generic-operation.thread-0 [000094] user=17.76% sys= 0.31% alloc= 113mb/s - hz._hzInstance_3_dev.generic-operation.thread-1 [000093] user=16.83% sys= 0.00% alloc= 111mb/s - hz._hzInstance_3_dev.generic-operation.thread-0 [000020] user=16.06% sys= 0.15% alloc= 108mb/s - hz._hzInstance_1_dev.generic-operation.thread-0 [000021] user=15.44% sys= 0.15% alloc= 110mb/s - hz._hzInstance_1_dev.generic-operation.thread-1 [000057] user=14.36% sys= 0.00% alloc= 110mb/s - hz._hzInstance_2_dev.generic-operation.thread-1 [000105] user=13.59% sys= 0.00% alloc= 72mb/s - hz._hzInstance_3_dev.cached.thread-1 [000079] user=13.43% sys= 0.15% alloc= 67mb/s - hz._hzInstance_2_dev.cached.thread-3 [000042] user=10.96% sys= 0.62% alloc= 65mb/s - hz._hzInstance_1_dev.cached.thread-2 [000174] user=10.65% sys= 0.31% alloc= 66mb/s - hz._hzInstance_3_dev.cached.thread-7 [000123] user= 8.96% sys= 0.00% alloc= 55mb/s - hz._hzInstance_4_dev.response [000129] user= 7.72% sys= 0.31% alloc= 21mb/s - hz._hzInstance_4_dev.generic-operation.thread-0 [000168] user= 6.95% sys= 0.62% alloc= 33mb/s - hz._hzInstance_1_dev.cached.thread-6 [000178] user= 7.57% sys= 0.00% alloc= 32mb/s - hz._hzInstance_2_dev.cached.thread-9 [000166] user= 6.48% sys= 0.46% alloc= 33mb/s - hz._hzInstance_1_dev.cached.thread-5 [000130] user= 6.02% sys= 0.62% alloc= 20mb/s - hz._hzInstance_4_dev.generic-operation.thread-1

Slide 13

Slide 13 text

SJK – первые шаги > java –jar sjk.jar gc -p 12345 Collecting GC stats ... [GC: PS Scavenge#1235 time: 3ms mem: Compressed Class Space: 3579k+0k->3579k[max:1048576k] PS Survivor Space: 3071k-2847k->224k[max:3072k] PS Old Gen: 42657k+440k->43097k[max:349696k] Metaspace: 27703k+0k->27703k PS Ede n Space: 164352k-164352k->0k[max:166400k]] [GC: PS Scavenge#1236 time: 7ms interval: 168ms mem: Compressed Class Space: 3579k+0k->3579k[max:1048576k,rat e:0.00kb/s] PS Survivor Space: 224k+1969k->2193k[max:5120k,rate:11722.47kb/s] PS Old Gen: 43097k+128k->43225k [max:349696k,rate:762.09kb/s] Metaspace: 27718k+0k->27718k[rate:0.00kb/s] PS Eden Space: 164352k-164352k->0k[ max:164352k,rate:-978285.71kb/s]] [GC: PS Scavenge#1237 time: 24ms interval: 293ms mem: Compressed Class Space: 3579k+0k->3579k[max:1048576k,ra te:0.00kb/s] PS Survivor Space: 2193k-895k->1297k[max:5120k,rate:-3056.71kb/s] PS Old Gen: 43225k+1832k->4505 7k[max:349696k,rate:6252.61kb/s] Metaspace: 27761k+0k->27761k[rate:0.00kb/s] PS Eden Space: 164352k-164352k-> 0k[max:164352k,rate:-560928.33kb/s]] [GC: PS Scavenge#1238 time: 15ms interval: 519ms mem: Compressed Class Space: 3579k+0k->3579k[max:1048576k,ra te:0.00kb/s] PS Survivor Space: 1297k-113k->1184k[max:1536k,rate:-219.07kb/s] PS Old Gen: 45057k+1032k->46089 k[max:349696k,rate:1988.62kb/s] Metaspace: 27769k+0k->27769k[rate:0.00kb/s] PS Eden Space: 164352k-164352k->0 k[max:168448k,rate:-316670.52kb/s]] Total PS Scavenge[ collections: 59 | avg: 0.0082 secs | total: 0.5 secs ]PS MarkSweep[ collections: 0 | avg: NaN se cs | total: 0.0 secs ] gc

Slide 14

Slide 14 text

ttop ttop > java –jar sjk.jar ttop -p 12345 2016-11-07T00:09:50.091+0400 Process summary process cpu=268.35% application cpu=244.42% (user=222.50% sys=21.93%) other: cpu=23.93% GC time=6.28% (young=1.62%, old=4.66%) heap allocation rate 1218mb/s safe point rate: 1.5 (events/s) avg. safe point pause: 43.24ms safe point sync time: 0.03% processing time: 6.39% (wallclock time) [000056] user=17.45% sys= 0.62% alloc= 106mb/s - hz._hzInstance_2_dev.generic-operation.thread-0 [000094] user=17.76% sys= 0.31% alloc= 113mb/s - hz._hzInstance_3_dev.generic-operation.thread-1 [000093] user=16.83% sys= 0.00% alloc= 111mb/s - hz._hzInstance_3_dev.generic-operation.thread-0 [000020] user=16.06% sys= 0.15% alloc= 108mb/s - hz._hzInstance_1_dev.generic-operation.thread-0 [000021] user=15.44% sys= 0.15% alloc= 110mb/s - hz._hzInstance_1_dev.generic-operation.thread-1 [000057] user=14.36% sys= 0.00% alloc= 110mb/s - hz._hzInstance_2_dev.generic-operation.thread-1 [000105] user=13.59% sys= 0.00% alloc= 72mb/s - hz._hzInstance_3_dev.cached.thread-1 [000079] user=13.43% sys= 0.15% alloc= 67mb/s - hz._hzInstance_2_dev.cached.thread-3 [000042] user=10.96% sys= 0.62% alloc= 65mb/s - hz._hzInstance_1_dev.cached.thread-2 [000174] user=10.65% sys= 0.31% alloc= 66mb/s - hz._hzInstance_3_dev.cached.thread-7 [000123] user= 8.96% sys= 0.00% alloc= 55mb/s - hz._hzInstance_4_dev.response [000129] user= 7.72% sys= 0.31% alloc= 21mb/s - hz._hzInstance_4_dev.generic-operation.thread-0 [000168] user= 6.95% sys= 0.62% alloc= 33mb/s - hz._hzInstance_1_dev.cached.thread-6 [000178] user= 7.57% sys= 0.00% alloc= 32mb/s - hz._hzInstance_2_dev.cached.thread-9 [000166] user= 6.48% sys= 0.46% alloc= 33mb/s - hz._hzInstance_1_dev.cached.thread-5 [000130] user= 6.02% sys= 0.62% alloc= 20mb/s - hz._hzInstance_4_dev.generic-operation.thread-1

Slide 15

Slide 15 text

ttop ttop > java –jar sjk.jar ttop -p 12345 2016-11-07T00:09:50.091+0400 Process summary process cpu=268.35% application cpu=244.42% (user=222.50% sys=21.93%) other: cpu=23.93% GC time=6.28% (young=1.62%, old=4.66%) heap allocation rate 1218mb/s safe point rate: 1.5 (events/s) avg. safe point pause: 43.24ms safe point sync time: 0.03% processing time: 6.39% (wallclock time) [000056] user=17.45% sys= 0.62% alloc= 106mb/s - hz._hzInstance_2_dev.generic-operation.thread-0 [000094] user=17.76% sys= 0.31% alloc= 113mb/s - hz._hzInstance_3_dev.generic-operation.thread-1 [000093] user=16.83% sys= 0.00% alloc= 111mb/s - hz._hzInstance_3_dev.generic-operation.thread-0 [000020] user=16.06% sys= 0.15% alloc= 108mb/s - hz._hzInstance_1_dev.generic-operation.thread-0 [000021] user=15.44% sys= 0.15% alloc= 110mb/s - hz._hzInstance_1_dev.generic-operation.thread-1 [000057] user=14.36% sys= 0.00% alloc= 110mb/s - hz._hzInstance_2_dev.generic-operation.thread-1 [000105] user=13.59% sys= 0.00% alloc= 72mb/s - hz._hzInstance_3_dev.cached.thread-1 [000079] user=13.43% sys= 0.15% alloc= 67mb/s - hz._hzInstance_2_dev.cached.thread-3 [000042] user=10.96% sys= 0.62% alloc= 65mb/s - hz._hzInstance_1_dev.cached.thread-2 [000174] user=10.65% sys= 0.31% alloc= 66mb/s - hz._hzInstance_3_dev.cached.thread-7 [000123] user= 8.96% sys= 0.00% alloc= 55mb/s - hz._hzInstance_4_dev.response [000129] user= 7.72% sys= 0.31% alloc= 21mb/s - hz._hzInstance_4_dev.generic-operation.thread-0 [000168] user= 6.95% sys= 0.62% alloc= 33mb/s - hz._hzInstance_1_dev.cached.thread-6 [000178] user= 7.57% sys= 0.00% alloc= 32mb/s - hz._hzInstance_2_dev.cached.thread-9 [000166] user= 6.48% sys= 0.46% alloc= 33mb/s - hz._hzInstance_1_dev.cached.thread-5 [000130] user= 6.02% sys= 0.62% alloc= 20mb/s - hz._hzInstance_4_dev.generic-operation.thread-1

Slide 16

Slide 16 text

ttop ttop > java –jar sjk.jar ttop -p 12345 2016-11-07T00:09:50.091+0400 Process summary process cpu=268.35% application cpu=244.42% (user=222.50% sys=21.93%) other: cpu=23.93% GC time=6.28% (young=1.62%, old=4.66%) heap allocation rate 1218mb/s safe point rate: 1.5 (events/s) avg. safe point pause: 43.24ms safe point sync time: 0.03% processing time: 6.39% (wallclock time) [000056] user=17.45% sys= 0.62% alloc= 106mb/s - hz._hzInstance_2_dev.generic-operation.thread-0 [000094] user=17.76% sys= 0.31% alloc= 113mb/s - hz._hzInstance_3_dev.generic-operation.thread-1 [000093] user=16.83% sys= 0.00% alloc= 111mb/s - hz._hzInstance_3_dev.generic-operation.thread-0 [000020] user=16.06% sys= 0.15% alloc= 108mb/s - hz._hzInstance_1_dev.generic-operation.thread-0 [000021] user=15.44% sys= 0.15% alloc= 110mb/s - hz._hzInstance_1_dev.generic-operation.thread-1 [000057] user=14.36% sys= 0.00% alloc= 110mb/s - hz._hzInstance_2_dev.generic-operation.thread-1 [000105] user=13.59% sys= 0.00% alloc= 72mb/s - hz._hzInstance_3_dev.cached.thread-1 [000079] user=13.43% sys= 0.15% alloc= 67mb/s - hz._hzInstance_2_dev.cached.thread-3 [000042] user=10.96% sys= 0.62% alloc= 65mb/s - hz._hzInstance_1_dev.cached.thread-2 [000174] user=10.65% sys= 0.31% alloc= 66mb/s - hz._hzInstance_3_dev.cached.thread-7 [000123] user= 8.96% sys= 0.00% alloc= 55mb/s - hz._hzInstance_4_dev.response [000129] user= 7.72% sys= 0.31% alloc= 21mb/s - hz._hzInstance_4_dev.generic-operation.thread-0 [000168] user= 6.95% sys= 0.62% alloc= 33mb/s - hz._hzInstance_1_dev.cached.thread-6 [000178] user= 7.57% sys= 0.00% alloc= 32mb/s - hz._hzInstance_2_dev.cached.thread-9 [000166] user= 6.48% sys= 0.46% alloc= 33mb/s - hz._hzInstance_1_dev.cached.thread-5 [000130] user= 6.02% sys= 0.62% alloc= 20mb/s - hz._hzInstance_4_dev.generic-operation.thread-1

Slide 17

Slide 17 text

ttop ttop > java –jar sjk.jar ttop -p 12345 2016-11-07T00:09:50.091+0400 Process summary process cpu=268.35% application cpu=244.42% (user=222.50% sys=21.93%) other: cpu=23.93% GC time=6.28% (young=1.62%, old=4.66%) heap allocation rate 1218mb/s safe point rate: 1.5 (events/s) avg. safe point pause: 43.24ms safe point sync time: 0.03% processing time: 6.39% (wallclock time) [000056] user=17.45% sys= 0.62% alloc= 106mb/s - hz._hzInstance_2_dev.generic-operation.thread-0 [000094] user=17.76% sys= 0.31% alloc= 113mb/s - hz._hzInstance_3_dev.generic-operation.thread-1 [000093] user=16.83% sys= 0.00% alloc= 111mb/s - hz._hzInstance_3_dev.generic-operation.thread-0 [000020] user=16.06% sys= 0.15% alloc= 108mb/s - hz._hzInstance_1_dev.generic-operation.thread-0 [000021] user=15.44% sys= 0.15% alloc= 110mb/s - hz._hzInstance_1_dev.generic-operation.thread-1 [000057] user=14.36% sys= 0.00% alloc= 110mb/s - hz._hzInstance_2_dev.generic-operation.thread-1 [000105] user=13.59% sys= 0.00% alloc= 72mb/s - hz._hzInstance_3_dev.cached.thread-1 [000079] user=13.43% sys= 0.15% alloc= 67mb/s - hz._hzInstance_2_dev.cached.thread-3 [000042] user=10.96% sys= 0.62% alloc= 65mb/s - hz._hzInstance_1_dev.cached.thread-2 [000174] user=10.65% sys= 0.31% alloc= 66mb/s - hz._hzInstance_3_dev.cached.thread-7 [000123] user= 8.96% sys= 0.00% alloc= 55mb/s - hz._hzInstance_4_dev.response [000129] user= 7.72% sys= 0.31% alloc= 21mb/s - hz._hzInstance_4_dev.generic-operation.thread-0 [000168] user= 6.95% sys= 0.62% alloc= 33mb/s - hz._hzInstance_1_dev.cached.thread-6 [000178] user= 7.57% sys= 0.00% alloc= 32mb/s - hz._hzInstance_2_dev.cached.thread-9 [000166] user= 6.48% sys= 0.46% alloc= 33mb/s - hz._hzInstance_1_dev.cached.thread-5 [000130] user= 6.02% sys= 0.62% alloc= 20mb/s - hz._hzInstance_4_dev.generic-operation.thread-1

Slide 18

Slide 18 text

ttop ttop > java –jar sjk.jar ttop -p 12345 2016-11-07T00:09:50.091+0400 Process summary process cpu=268.35% application cpu=244.42% (user=222.50% sys=21.93%) other: cpu=23.93% GC time=6.28% (young=1.62%, old=4.66%) heap allocation rate 1218mb/s safe point rate: 1.5 (events/s) avg. safe point pause: 43.24ms safe point sync time: 0.03% processing time: 6.39% (wallclock time) [000056] user=17.45% sys= 0.62% alloc= 106mb/s - hz._hzInstance_2_dev.generic-operation.thread-0 [000094] user=17.76% sys= 0.31% alloc= 113mb/s - hz._hzInstance_3_dev.generic-operation.thread-1 [000093] user=16.83% sys= 0.00% alloc= 111mb/s - hz._hzInstance_3_dev.generic-operation.thread-0 [000020] user=16.06% sys= 0.15% alloc= 108mb/s - hz._hzInstance_1_dev.generic-operation.thread-0 [000021] user=15.44% sys= 0.15% alloc= 110mb/s - hz._hzInstance_1_dev.generic-operation.thread-1 [000057] user=14.36% sys= 0.00% alloc= 110mb/s - hz._hzInstance_2_dev.generic-operation.thread-1 [000105] user=13.59% sys= 0.00% alloc= 72mb/s - hz._hzInstance_3_dev.cached.thread-1 [000079] user=13.43% sys= 0.15% alloc= 67mb/s - hz._hzInstance_2_dev.cached.thread-3 [000042] user=10.96% sys= 0.62% alloc= 65mb/s - hz._hzInstance_1_dev.cached.thread-2 [000174] user=10.65% sys= 0.31% alloc= 66mb/s - hz._hzInstance_3_dev.cached.thread-7 [000123] user= 8.96% sys= 0.00% alloc= 55mb/s - hz._hzInstance_4_dev.response [000129] user= 7.72% sys= 0.31% alloc= 21mb/s - hz._hzInstance_4_dev.generic-operation.thread-0 [000168] user= 6.95% sys= 0.62% alloc= 33mb/s - hz._hzInstance_1_dev.cached.thread-6 [000178] user= 7.57% sys= 0.00% alloc= 32mb/s - hz._hzInstance_2_dev.cached.thread-9 [000166] user= 6.48% sys= 0.46% alloc= 33mb/s - hz._hzInstance_1_dev.cached.thread-5 [000130] user= 6.02% sys= 0.62% alloc= 20mb/s - hz._hzInstance_4_dev.generic-operation.thread-1

Slide 19

Slide 19 text

ttop ttop > java –jar sjk.jar ttop -p 12345 -c 2018-06-19T16:10:50.510+0300 Process summary process cpu=220.80% application cpu=206.79% (user=187.90% sys=18.88%) other: cpu=14.01% thread count: 166 GC time=3.41% (young=3.41%, old=0.00%) heap allocation rate 878mb/s safe point rate: 5.6 (events/s) avg. safe point pause: 6.76ms safe point sync time: 0.07% processing time: 3.75% (wallclock time) [000058] user=14.48% sys= 0.16% wait=50.84/s(84.10%) block= 0.20/s( 0.00%) alloc= 80mb/s - hz._hzInstance_2_dev.gene [000057] user=14.32% sys= 0.16% wait=51.55/s(84.03%) block= 0.20/s( 0.00%) alloc= 76mb/s - hz._hzInstance_2_dev.gene [000022] user=13.69% sys= 0.31% wait=51.95/s(83.96%) block= 0/s( 0.00%) alloc= 80mb/s - hz._hzInstance_1_dev.gene [000128] user=13.53% sys= 0.00% wait= 1.21/s(85.41%) block= 0/s( 0.00%) alloc= 56mb/s - hz._hzInstance_4_dev.resp [000095] user=13.38% sys= 0.00% wait=51.05/s(84.36%) block= 0/s( 0.00%) alloc= 77mb/s - hz._hzInstance_3_dev.gene [000182] user=12.75% sys= 0.63% wait=171.0/s(85.89%) block= 0.10/s( 0.05%) alloc= 61mb/s - hz._hzInstance_3_dev.cach [000021] user=12.28% sys= 0.00% wait=51.35/s(84.00%) block= 0.20/s( 0.00%) alloc= 76mb/s - hz._hzInstance_1_dev.gene [000187] user=11.49% sys= 0.16% wait=143.0/s(87.12%) block= 0/s( 0.00%) alloc= 50mb/s - hz._hzInstance_2_dev.cach [000094] user=11.17% sys= 0.16% wait=52.66/s(84.55%) block= 0.30/s( 0.10%) alloc= 78mb/s - hz._hzInstance_3_dev.gene [000167] user=10.39% sys= 0.00% wait=153.0/s(88.15%) block= 0/s( 0.00%) alloc= 45mb/s - hz._hzInstance_1_dev.cach [000186] user= 7.24% sys= 0.31% wait=126.5/s(91.44%) block= 0/s( 0.00%) alloc= 33mb/s - hz._hzInstance_1_dev.cach [000116] user= 7.08% sys= 0.16% wait=88.57/s(91.20%) block= 0.10/s( 0.00%) alloc= 34mb/s - hz._hzInstance_3_dev.cach [000135] user= 6.61% sys= 0.47% wait=184.9/s(92.36%) block= 0/s( 0.00%) alloc= 15mb/s - hz._hzInstance_4_dev.gene [000189] user= 7.08% sys= 0.00% wait=113.9/s(91.53%) block= 0/s( 0.00%) alloc= 34mb/s - hz._hzInstance_2_dev.cach [000134] user= 5.98% sys= 0.31% wait=193.1/s(93.39%) block= 0/s( 0.00%) alloc= 14mb/s - hz._hzInstance_4_dev.gene

Slide 20

Slide 20 text

All of SJK tools  ttop  gc  hh  hs  jcmd  jps  vminfo  dexp  jfr2json Sampling profiler  stcap  stcpy  ssa  flame  prfi single executable jar (< 2Mib) https://github.com/aragozin/jvm-tools JMX  mprx  mx  mxdump  mxping

Slide 21

Slide 21 text

А что про GC? Скорость аллокации объектов young/old Статистика “мёртвых” объектов Анализ БОЛЬШИХ дампов памяти

Slide 22

Slide 22 text

Heap Histogram (hh) > java –jar sjk.jar hh -p 12345 –dead –n 20 # Instances Bytes Type 1: 2923126 119248376 [C 2: 127292 75552608 [B 3: 2367217 56813208 java.lang.String 4: 464272 14856704 java.util.concurrent.ConcurrentHashMap$Node 5: 589853 14156472 info.ragozin.perflab.hazelagg.SliceKey 6: 111178 11562512 java.io.ObjectStreamClass 7: 162932 7820736 java.util.HashMap 8: 325582 7813968 java.lang.StringBuilder 9: 176100 6365688 [Ljava.lang.Object; 10: 98217 6288752 [I 11: 297 5708880 [Ljava.util.concurrent.ConcurrentHashMap$Node; 12: 127056 5082240 java.io.ObjectStreamField 13: 153958 4926656 java.util.HashMap$Node 14: 153933 4925856 com.hazelcast.util.ConcurrentReferenceHashMap$HashEntry 15: 127427 4077664 com.hazelcast.nio.Address 16: 167599 4022376 java.lang.Long 17: 167153 4011672 java.util.ArrayList 18: 81016 3240640 java.math.BigDecimal 19: 80805 3232200 java.util.Collections$SingletonMap 20: 127426 3058224 info.ragozin.perflab.hazelagg.PositionAggregation$CFactory$1 Total 9473688 392379120

Slide 23

Slide 23 text

Heap Histogram (hh) sjk hh = jmap -histo sjk hh --live = jmap -histo:live sjk hh --dead => diff(jmap -histo, jmap -histo:live) sjk hh --deadYoung => Full GC, wait 10 seconds, hh --dead

Slide 24

Slide 24 text

HeapLib Спин-офф проект SJK - https://github.com/aragozin/heaplib • Основан на коде NetBeans/VisualVM • Позволяет работать с 100+GiB дампами • Ориентирован на использование API • HeapPath язык селекторов для объектов дампа • Режим без индексов на диске • Работа со сжатыми (.gz) дампами на прямую https://github.com/aragozin/heapunit - проверки состояния графов объектов в тестах, например тесты на утечки

Slide 25

Slide 25 text

Сэмплирование потоков Task.run() wait() process() getBody() read() parse() handle() load() read() Time encode() wait() process() getBody() read() parse() handle() load() read() encode() wait() process() getBody() read() parse() handle() encode() 10 Task.run 7 3 process() 4 handle() 3 encode() 2 ... 1 ... 1 load() geBody() 2 1 read() parse() 1 3 wait() ...

Slide 26

Slide 26 text

SJK как профайлер Сбор сэмплсэта – SJK, JFR, jstack, VisualVM, perf Параметры фильтра Визуализация Медитация Итерация

Slide 27

Slide 27 text

Источники данных  sjk stcap – сэмплирование по JMX  VisualVM snapshots  JDK Flight Recorder method sampling, native method sampling, allocation, exceptions  jstack – в виде набора текстовых файлов  Linux perf recordings

Slide 28

Slide 28 text

Критерии фильтрации По имени потока -tn ‘.*worker.*’ По временной метке -tr 10:00:00-14:59:59 По стэктрейсу -tf **.jdbc -tf **!**.Unsafe.park https://github.com/aragozin/jvm-tools/blob/master/sjk-core/src/main/resources/org/gridkit/jvmtool/cmd/ssa-help.md

Slide 29

Slide 29 text

Визуалтзация  ssa --print  ssa --histo  ssa --thread-info  ssa --flame (SVG) or flame (HTML)  ssa --categorize

Slide 30

Slide 30 text

Гистограмма методов > java –jar sjk.jar ssa -f jboss-10k.std -tt org.hibernate --histo 3064 69% 3064 1 0% org.hibernate.ejb.QueryImpl.getResultList(QueryImpl.java:264) 2891 65% 2891 0 0% org.hibernate.internal.SessionImpl.autoFlushIfRequired(SessionImpl.java:1204) 2790 62% 2790 0 0% org.hibernate.internal.SessionImpl.list(SessionImpl.java:1261) 2534 57% 2534 0 0% org.hibernate.event.internal.DefaultAutoFlushEventListener.onAutoFlush(DefaultAutoFlushEv 2014 45% 2014 0 0% org.hibernate.event.internal.AbstractFlushingEventListener.flushEverythingToExecutions(Ab 1957 44% 1957 1 0% org.hibernate.event.internal.AbstractFlushingEventListener.flushEntities(AbstractFlushing 1419 32% 1419 2 0% org.hibernate.event.internal.AbstractVisitor.processEntityPropertyValues(AbstractVisitor. 1235 27% 1235 0 0% oracle.jdbc.driver.T4CTTIfun.doRPC(T4CTTIfun.java:249) 1230 27% 1230 0 0% oracle.net.ns.NetInputStream.read(NetInputStream.java:249) 1229 27% 1229 0 0% oracle.jdbc.driver.T4CSocketInputStreamWrapper.read(T4CSocketInputStreamWrapper.java:79) 1229 27% 1229 0 0% oracle.jdbc.driver.T4CTTIfun.receive(T4CTTIfun.java:390) 1229 27% 1229 0 0% oracle.jdbc.driver.T4CSocketInputStreamWrapper.readNextPacket(T4CSocketInputStreamWrapper 1229 27% 1229 0 0% oracle.jdbc.driver.T4CMAREngineStream.unmarshalUB1(T4CMAREngineStream.java:426) 1229 27% 1229 0 0% oracle.net.ns.NetInputStream.read(NetInputStream.java:171) 1229 27% 1229 0 0% oracle.net.ns.NetInputStream.read(NetInputStream.java:89) 1227 27% 1227 0 0% oracle.jdbc.driver.T4CPreparedStatement.doOall8(T4CPreparedStatement.java:215) 1225 27% 1225 0 0% oracle.jdbc.driver.T4C8Oall.doOALL(T4C8Oall.java:566) 1205 27% 1205 0 0% oracle.jdbc.driver.T4CPreparedStatement.doOall8(T4CPreparedStatement.java:58) 1203 27% 1203 0 0% java.net.SocketInputStream.read(SocketInputStream.java:152) 1203 27% 1203 0 0% java.net.SocketInputStream.read(SocketInputStream.java:122) 1203 27% 1203 0 0% oracle.net.ns.DataPacket.receive(DataPacket.java:105) 1203 27% 1203 1203 27% java.net.SocketInputStream.socketRead0(Native Method) 1203 27% 1203 0 0% oracle.net.ns.NetInputStream.getNextPacket(NetInputStream.java:305) 1203 27% 1203 0 0% oracle.net.ns.Packet.receive(Packet.java:311)

Slide 31

Slide 31 text

ssa --thread-info > java –jar sjk.jar ssa –f dump.sjk –thread-info Name Count On CPU Alloc RUNNABLE Native main 812 0.0% 4381/s 0.0% 100.0% Reference Handler 812 0.0% 0/s 0.0% 100.0% hz._hzInstance_1_dev.response 812 1.0% 2917k/s 2.5% 99.8% hz._hzInstance_1_dev.partition-o 812 0.0% 419/s 0.1% 100.0% hz._hzInstance_1_dev.partition-o 812 0.0% 455/s 0.0% 100.0% hz._hzInstance_1_dev.priority-ge 812 0.0% 54/s 0.0% 100.0% hz._hzInstance_1_dev.generic-ope 812 8.1% 46m/s 14.2% 97.9% hz._hzInstance_1_dev.generic-ope 812 8.3% 44m/s 12.1% 98.2% hz._hzInstance_1_dev.SlowOperati 812 0.0% 0/s 0.0% 100.0% hz._hzInstance_1_dev.event-1 812 0.0% 0/s 0.0% 100.0% hz._hzInstance_1_dev.event-2 812 0.0% 0/s 0.0% 100.0% hz._hzInstance_1_dev.wait-notify 812 0.0% 88/s 0.0% 100.0% hz._hzInstance_1_dev.migration 812 0.0% 25/s 0.0% 100.0% pool-1-thread-1 812 0.0% 117/s 0.0% 100.0% pool-1-thread-2 812 0.0% 34/s 0.0% 100.0% hz._hzInstance_1_dev.InvocationM 812 0.0% 172/s 0.4% 99.6% hz._hzInstance_1_dev.cached.thre 812 2.5% 11m/s 5.2% 95.6% hz._hzInstance_1_dev.cached.thre 812 4.6% 22m/s 7.1% 94.0% hz._hzInstance_1_dev.IO.thread-i 812 0.3% 1266k/s 100.0% 99.9% hz._hzInstance_1_dev.IO.thread-i 812 0.5% 1240k/s 100.0% 100.0% hz._hzInstance_1_dev.IO.thread-o 812 0.9% 2859/s 100.0% 100.0% hz._hzInstance_1_dev.IO.thread-o 812 1.0% 2744/s 100.0% 100.0%

Slide 32

Slide 32 text

ssa --thread-info java –jar sjk.jar ssa –f dump.sjk –thread-info -si NAME COUNT CPU SYS ALLOC S:WAITING S:TIMED_WAITING S erialization=**.Object*Stream Name Count On CPU System Alloc WAITING TIMED_WAITING Serialization main 812 0.0% 0.0% 4381/s 0.2% 99.8% 0.0% Reference Handler 812 0.0% 0.0% 0/s 100.0% 0.0% 0.0% Finalizer 812 0.0% 0.0% 0/s 100.0% 0.0% 0.0% hz._hzInstance_1_dev.scheduled 812 0.0% 0.0% 1104/s 0.0% 99.9% 0.0% hz._hzInstance_1_dev.response 812 1.0% 0.1% 2917k/s 97.5% 0.0% 0.5% hz._hzInstance_1_dev.partition-o 812 0.0% 0.0% 419/s 99.9% 0.0% 0.0% hz._hzInstance_1_dev.priority-ge 812 0.0% 0.0% 54/s 100.0% 0.0% 0.0% hz._hzInstance_1_dev.generic-ope 812 8.1% 0.1% 46m/s 85.8% 0.0% 13.7% hz._hzInstance_1_dev.generic-ope 812 8.3% 0.1% 44m/s 87.9% 0.0% 10.7% hz._hzInstance_1_dev.SlowOperati 812 0.0% 0.0% 0/s 0.0% 100.0% 0.0% hz._hzInstance_1_dev.event-1 812 0.0% 0.0% 0/s 100.0% 0.0% 0.0% hz._hzInstance_1_dev.wait-notify 812 0.0% 0.0% 88/s 0.0% 100.0% 0.0% hz._hzInstance_1_dev.migration 812 0.0% 0.0% 25/s 0.0% 100.0% 0.0% pool-1-thread-1 812 0.0% 0.0% 117/s 3.8% 96.2% 0.0% pool-1-thread-2 812 0.0% 0.0% 34/s 96.2% 3.8% 0.0% hz._hzInstance_1_dev.InvocationM 812 0.0% 0.0% 172/s 0.0% 99.6% 0.0% hz._hzInstance_1_dev.cached.thre 812 2.5% 0.1% 11m/s 18.7% 76.1% 2.2% hz._hzInstance_1_dev.cached.thre 812 4.6% 0.1% 22m/s 25.5% 67.4% 3.7% hz._hzInstance_1_dev.IO.thread-i 812 0.1% 0.1% 105k/s 0.0% 0.0% 0.0% hz._hzInstance_1_dev.IO.thread-o 812 0.9% 0.7% 2859/s 0.0% 0.0% 0.0% hz._hzInstance_2_dev.scheduled 812 0.1% 0.0% 1169/s 0.0% 99.9% 0.0% hz._hzInstance_2_dev.response 812 0.9% 0.0% 2976k/s 97.2% 0.0% 2.7% hz._hzInstance_2_dev.partition-o 812 0.0% 0.0% 461/s 100.0% 0.0% 0.0% hz._hzInstance_2_dev.partition-o 812 0.1% 0.0% 394/s 100.0% 0.0% 0.0%

Slide 33

Slide 33 text

flame HTML “Горящие” графы

Slide 34

Slide 34 text

ssa --flame SVG “Горящие” графы

Slide 35

Slide 35 text

Jboss в огне JBoss + Seam + Hibernate

Slide 36

Slide 36 text

Анализ по фреймворкам Command sjk ssa -f tracedump.std --categorize -tf **.CoyoteAdapter.service -nc JDBC=**.jdbc Hibernate=org.hibernate "Facelets compile=com.sun.faces.facelets.compiler.Compiler.compile" "Seam bijection=org.jboss.seam.**.aroundInvoke/!**.proceed" JSF.execute=com.sun.faces.lifecycle.LifecycleImpl.execute JSF.render=com.sun.faces.lifecycle.LifecycleImpl.render Other=** Report Total samples 2732050 100.00% JDBC 405439 14.84% Hibernate 802932 29.39% Facelets compile 395784 14.49% Seam bijection 385491 14.11% JSF.execute 290355 10.63% JSF.render 297868 10.90% Other 154181 5.64% 0.00% 20.00% 40.00% 60.00% 80.00% 100.00% Time Other JSF.render JSF.execute Seam bijection Facelets compile Hibernate JDBC Excel

Slide 37

Slide 37 text

Работа с MBean`ами sjk mxdump - все mbean`ы в JSON sjk mx -mi – чтение мета данных -mg – чтение (таблица, CSV, JSON) -ms – запись -mc – вызов операции

Slide 38

Slide 38 text

Удалённая работа с jcmd Дамп потоков java -jar sjk.jar jcmd -s myhost:9099 -c Thread.print Запуск JFR сессии* java -jar sjk.jar jcmd -s myhost:9099 -c JFR.start * - SJK пока не умеет скачивать JFR дамп удалённо, используйте Mission Control.

Slide 39

Slide 39 text

Часть 2 Контейнеры и проклятие JMX

Slide 40

Slide 40 text

Особенности JMX/RMI Адрес RMI хоста должен быть доступен с клиента!

Slide 41

Slide 41 text

Что делать с JMX в контейнерах? Стратегии настройки JMX Использовать только локально приемлемо для мониторинговых агентов Настройка JMX на публичный IP необходимо знать IP Настройка IP на туннельный доступ необходимо иметь доступ к туннелю прямой доступ к JMX работать не будет https://blog.ragozin.info/2023/09/curse-of-jmx.html Радикальные решения Jolokia – JMX over HTTP https://jolokia.org/ SJK JMX proxy https://github.com/aragozin/jvm-tools/ (позволяет включать JMX без рестарта, через консоль контейнера)

Slide 42

Slide 42 text

Стратегия “туннельный доступ” -Djava.rmi.server.hostname=127.0.0.1 -Dcom.sun.management.jmxremote -Dcom.sun.management.jmxremote.authenticate=false -Dcom.sun.management.jmxremote.ssl=false -Dcom.sun.management.jmxremote.port=55555 -Dcom.sun.management.jmxremote.rmi.port=5555

Slide 43

Slide 43 text

Диагностика JMX SJK – https://github.com/aragozin/jvm-tools sjk.jar mxping -s … Детальная диагностика JMX хендшейка с распечаткой адресов > java -jar sjk.jar mxping -s 127.0.0.1:34000 SJK is running on: OpenJDK 64-Bit Server VM 25.275-b01 (BellSoft) Java home: C:\Java\jdk1.8.0_275+1_bellsoft_x64\jre Try to connect via TLS Establishing connection to 127.0.0.1:34000 Failed to connect using TLS: java.rmi.ConnectIOException: error during JRMP connection establishment; nested exception is: javax.net.ssl.SSLHandshakeException: Remote host terminated the handshake Try to use plain socket Establishing connection to 127.0.0.1:34000 Establishing connection to 192.168.100.1:34000 Remote VM: OpenJDK 64-Bit Server VM 25.275-b01 (BellSoft)

Slide 44

Slide 44 text

SJK JMX прокси В контейнере jcmd 1234 \ ManagementAgent.start\ jmxremote.authenticate=false\ jmxremote.ssl=false\ jmxremote.port=6666\ jmxremote.rmi.port=5555 Туннель в контейнер 5555 -> 6666 java -jar sjk.jar mprx -s server.local:4444 --force-address -b 127.0.0.1:5555

Slide 45

Slide 45 text

Перерыв Алексей Рагозин [email protected] https://aragozin.timepad.ru https://blog.ragozin.info

Slide 46

Slide 46 text

Анонсы Диагностика JVM из командной строки Вебинар – 23 января https://training.ragozin.info/w20240123 Эффективное профилирование Java приложений Онлайн курс – 26-28 февраля 3 модуля * 3 занятия * 3 часа Промокод: JUGMSK (20 000 за первый модуль) https://training.ragozin.info/online

Slide 47

Slide 47 text

Часть 3 Автоматизируем профилирование

Slide 48

Slide 48 text

API для диагностики  org.gridkit.jvmtool:sjk-core  JFR API  JMX API  jcmd

Slide 49

Slide 49 text

API для диагностики  org.gridkit.jvmtool:sjk-core  Сэмплирование потоков, например в фоне как JFR  SJK имеет свой сжатый формат сэмплсетов, dexp позволяет экспортировать данные  Генерация флейм графов (SVG, HTML)  JFR API  JMX API  jcmd

Slide 50

Slide 50 text

API для диагностики  org.gridkit.jvmtool:sjk-core  JFR API  Управлением JFR  Чтение событий JFR из файлов  Создание своих прикладных событий  JMX API  jcmd

Slide 51

Slide 51 text

API для диагностики  org.gridkit.jvmtool:sjk-core  JFR API  JMX API Низкоуровневый протокол  Доступ к прикладным Mbean`ам  jcmd

Slide 52

Slide 52 text

API для диагностики  org.gridkit.jvmtool:sjk-core  JFR API  JMX API  jcmd  Доступна удалённо через JMX

Slide 53

Slide 53 text

HeapLib Спин-офф проект SJK - https://github.com/aragozin/heaplib • Основан на коде NetBeans/VisualVM • Позволяет работать с 100+GiB дампами • Ориентирован на использование API • HeapPath язык селекторов для объектов дампа • Режим без индексов на диске • Работа со сжатыми (.gz) дампами на прямую https://github.com/aragozin/heapunit - проверки состояния графов объектов в тестах, например тесты на утечки

Slide 54

Slide 54 text

Спасибо Алексей Рагозин [email protected] https://aragozin.timepad.ru https://blog.ragozin.info

Slide 55

Slide 55 text

Анонсы Диагностика JVM из командной строки Вебинар – 23 января https://training.ragozin.info/w20240123 Эффективное профилирование Java приложений Онлайн курс – 26-28 февраля 3 модуля * 3 занятия * 3 часа Промокод: JUGMSK (20 000 за первый модуль) https://training.ragozin.info/online