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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

Сэмплирование потоков 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() ...

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

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

Критерии фильтрации По имени потока -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

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

Гистограмма методов > 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)

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%

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%

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

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

Jboss в огне JBoss + Seam + Hibernate

Анализ по фреймворкам 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

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

Удалённая работа с 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.

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

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

Что делать с 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 без рестарта, через консоль контейнера)

Стратегия “туннельный доступ” -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

Диагностика 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)

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

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

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

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

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

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

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

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

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

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

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

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