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

Алексей Рагозин — SJK спешит на помощь

Moscow JUG
January 19, 2024

Алексей Рагозин — SJK спешит на помощь

SJK (Swiss Java Knife)github.com/aragozin/jvm-tools — начал свою историю 2011 году с простых инструментов мониторинга потоков и сборщика мусора в JVM. С тех пор он оброс значительным числом разноплановых функций, которые могут понадобиться Java-инженеру или SRE, работающему с JVM.

SJK — это выполняемый jar файл, который можно скопировать и использовать на сервере (или даже в контейнере). В то же время SJK может быть использован, как библиотека для встраивания диагностики в прикладной код.

На данной встрече поговорим о всём спектре возможностей SJK, которые в свою очередь можно разделить на несколько категорий:
- ad hoc диагностика JVM, анализ производительности и профилирование;
- анализ данных, собранных при профилировании (в том числе, данные собранные другими инструментами, такими как Java Flight Recorder и perf);
- манипуляции с JMX: вызовы, скраппинг, проксирование и пр.;
- использование SJK в качестве библиотеки.

Moscow JUG

January 19, 2024
Tweet

More Decks by Moscow JUG

Other Decks in Programming

Transcript

  1. Анонсы Диагностика JVM из командной строки Вебинар – 23 января

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

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

    JMX перерыв Автоматизируем профилирование
  4. Экосистема Java профайлеров “Настольные” инструменты - работают локально, либо надо

    настраивать JMX и доступ к сети Системы типа APM – требуют инфраструктуры и настройки Инструменты JDK – работают из терминала, но не дают того что хочется
  5. Что есть в OpenJDK? jps – список Java процессов jmap

    – дампы и гистограммы памяти jstack – дамп потоков jstat – некоторые метрики JVM jinfo – информация о параметрах JVM и system properties jcmd – one tool to rule them all! jhsdb – postmortem диагностика (Java 9 and above)
  6. 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
  7. А что же я хочу увидеть? • Потребление CPU по

    потокам информация доступна в JMX начиная с Java 6! • Метрики GC скорость заполнения Eden статистику мертвых объектов
  8. 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
  9. 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
  10. 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
  11. 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
  12. 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
  13. 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
  14. 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
  15. 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
  16. 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
  17. 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
  18. 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
  19. HeapLib Спин-офф проект SJK - https://github.com/aragozin/heaplib • Основан на коде

    NetBeans/VisualVM • Позволяет работать с 100+GiB дампами • Ориентирован на использование API • HeapPath язык селекторов для объектов дампа • Режим без индексов на диске • Работа со сжатыми (.gz) дампами на прямую https://github.com/aragozin/heapunit - проверки состояния графов объектов в тестах, например тесты на утечки
  20. Сэмплирование потоков 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() ...
  21. SJK как профайлер Сбор сэмплсэта – SJK, JFR, jstack, VisualVM,

    perf Параметры фильтра Визуализация Медитация Итерация
  22. Источники данных  sjk stcap – сэмплирование по JMX 

    VisualVM snapshots  JDK Flight Recorder method sampling, native method sampling, allocation, exceptions  jstack – в виде набора текстовых файлов  Linux perf recordings
  23. Критерии фильтрации По имени потока -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
  24. Визуалтзация  ssa --print  ssa --histo  ssa --thread-info

     ssa --flame (SVG) or flame (HTML)  ssa --categorize
  25. Гистограмма методов > 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)
  26. 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%
  27. 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%
  28. Анализ по фреймворкам 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
  29. Работа с MBean`ами sjk mxdump <jmx details> - все mbean`ы

    в JSON sjk mx <jmx details> -mi – чтение мета данных -mg – чтение (таблица, CSV, JSON) -ms – запись -mc – вызов операции
  30. Удалённая работа с 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.
  31. Что делать с 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 без рестарта, через консоль контейнера)
  32. Диагностика JMX SJK – https://github.com/aragozin/jvm-tools sjk.jar mxping -s <hostname:port> …

    Детальная диагностика 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)
  33. 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
  34. Анонсы Диагностика JVM из командной строки Вебинар – 23 января

    https://training.ragozin.info/w20240123 Эффективное профилирование Java приложений Онлайн курс – 26-28 февраля 3 модуля * 3 занятия * 3 часа Промокод: JUGMSK (20 000 за первый модуль) https://training.ragozin.info/online
  35. API для диагностики  org.gridkit.jvmtool:sjk-core  Сэмплирование потоков, например в

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

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

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

    API  jcmd  Доступна удалённо через JMX
  39. HeapLib Спин-офф проект SJK - https://github.com/aragozin/heaplib • Основан на коде

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

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