Как jcmd помогает настроить JVM для low-latency

Утилиту jcmd добавили в Java 7 и с тех пор она считается главной утилитой, с помощью которой вы отныне будете заглядывать внутрь JVM и замерять все параметры ее работы. Все остальные утилиты типа jps, jstack, jinfo и проч. считаются теперь устаревшими и скоро в каком-то из будущих релизов JDK будут удалены. Предполагается, что jcmd заменит их всех. Давайте посмотрим, как работает утилита, и что полезного с ее помощью можно узнать о работающем приложении и как эта информация может нам пригодиться для настройки JVM и самого приложения с целью достижения low-latency.

Стоит отметить, что информация, которую выдает jcmd может заметно отличаться по полноте и структуре от того, что выдают старые утилиты. В JDK15 старые утилиты еще поставляются, но ничто не гарантирует, что они там останутся в следующих релизах.

Формат команд jcmd простой и прекрасно описан в документации на сайте Oracle, например вот вариант для Java 8 LTS, Java11 LTS, и для свеженькой Java15.

$jcmd <команда>

Для начала давайте запустим простое приложение. Для этого подойдет простой скрипт на groory, который имитирует web-приложение. Этот скрипт hello.groovy мы запустим с помощью Spring CLI.

@RestController
class WebApplication {
    @RequestMapping("/")
    String home() {
        "Hello World!"
    }
}

Скрипт запускается из командной строки:

$spring run hello.groovy -- --server.port=8888

Spring Boot запустит веб-сервер, ожидающий http-запросы на локальном порту 8888. Наберите в браузере http://localhost:8888/ и вы увидите ответ «Hello World!». Разумеется, данный пример элементарен и low-latency от него не требуется, но для демонстрации возможностей jcmd — вполне подойдет.

Список запущенных java-программ

Простой запуск jcmd из командной строки даст список запущенных java-программ и их pid. Раньше такой список мы могли получить с помощью утилиты jps.

$jcmd
16528 jdk.jcmd/sun.tools.jcmd.JCmd 
17316 org.springframework.boot.loader.JarLauncher run hello.groovy -- --server.port=8888

pid нашего web-приложения — 17316. Теперь все остальные команды jcmd мы будем адресовывать нашей программе, используя pid в качестве первого параметра.

Список команд, поддерживаемых JVM

Вполне может быть, что на вашей машине работают Java-приложения на JVM разных версий. Например, одна программа работает на Java8, а вторая — на чем-то более свежем — скажем, на Java15. JVM разных версий Java поддерживают разный набор команд, и на некоторые команды Java8 может сказать «Not supported». Поэтому с помощью jcmd мы можем узнать, какие команды есть в нашем распоряжении:

$jcmd 17316 help

Список выглядит так:

17316: The following commands are available: 
Compiler.CodeHeap_Analytics 
Compiler.codecache 
Compiler.codelist 
Compiler.directives_add 
Compiler.directives_clear 
Compiler.directives_print 
Compiler.directives_remove 
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 
Thread.print 
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 
help 

For more information about a specific command use 'help '.

Команды сгруппированы в группы:

  • Compiler — информация о JIT-компиляторе
  • GC — информация о сборщике мусора,
  • JFR — информация о модуле Flight Recorder, встреонном в JVM
  • JVMTI — информация об Java-агентах
  • ManagementAgent — информация о jmx-агентах
  • Thread — информация о потоках
  • и VM — информация о состоянии виртуальной машины

Если help вызвать с параметром -all, под каждой командой появится еще и объяснение, что она делает.

$jcmd <pid> help -all

Например, так выглядит фрагмент с описанием команды VM.version:

VM.version
        Print JVM version information.

Счетчики производительности

В списке отсутствует одна специальная команда PerfCounter.print, которая может очень пригодиться при настройке JVM для low-latency:

$jcmd <pid> PerfCounter.print

Эта команда выдает значения внутренних счетчиков производительности JVM, многие из которых расскажут вам, что и как происходит внутри вашего приложения и JVM, на которой оно работает. Так выглядит сокращенный листинг этих счетчиков:

17316:
java.ci.totalTime=125699679
java.cls.loadedClasses=6201
java.cls.sharedLoadedClasses=1149
java.cls.sharedUnloadedClasses=0
java.cls.unloadedClasses=0
java.property.java.class.path="D:\tools\spring-cli\bin\..\lib\spring-boot-cli-2.3.3.RELEASE.jar"
java.property.java.home="C:\java\java15"
...
java.property.java.version="15"
java.property.java.vm.info="mixed mode, sharing"
java.property.java.vm.name="Java HotSpot(TM) 64-Bit Server VM"
java.property.java.vm.specification.name="Java Virtual Machine Specification"
java.property.java.vm.specification.vendor="Oracle Corporation"
java.property.java.vm.specification.version="15"
java.property.java.vm.vendor="Oracle Corporation"
java.property.java.vm.version="15+36-1562"
java.property.jdk.debug="release"
java.rt.vmArgs=""
java.rt.vmFlags=""
java.threads.daemon=19
java.threads.live=23
java.threads.livePeak=24
java.threads.started=28
sun.ci.lastFailedMethod="java/util/HashSet add"
sun.ci.lastFailedType=1
sun.ci.lastInvalidatedMethod=""
sun.ci.lastInvalidatedType=0
sun.ci.lastMethod="org/apache/catalina/core/ContainerBase findChildren"
sun.ci.lastSize=47
sun.ci.lastType=1
sun.ci.nmethodBucketsAllocated=2765
sun.ci.nmethodBucketsDeallocated=681
sun.ci.nmethodBucketsStale=0
sun.ci.nmethodBucketsStaleAccumulated=0
sun.ci.nmethodCodeSize=7164384
sun.ci.nmethodSize=10352904
sun.ci.osrBytes=19684
sun.ci.osrCompiles=37
sun.ci.osrTime=2942894
sun.ci.standardBytes=723577
sun.ci.standardCompiles=4842
sun.ci.standardTime=122756785
sun.ci.threads=3
sun.ci.totalBailouts=1
sun.ci.totalCompiles=4879
sun.ci.totalInvalidates=0
sun.classloader.findClassTime=2332746900
sun.classloader.findClasses=4461
sun.classloader.parentDelegationTime=436135800
sun.cls.appClassBytes=22248897
sun.cls.appClassLoadCount=9414
sun.cls.appClassLoadTime=28732474
sun.cls.appClassLoadTime.self=20780323
sun.cls.classInitTime=14895959
sun.cls.classInitTime.self=8521571
sun.cls.classLinkedTime=12289318
sun.cls.classLinkedTime.self=1216344
sun.cls.classVerifyTime=11068233
sun.cls.classVerifyTime.self=3509266
sun.cls.defineAppClassTime=10253424
sun.cls.defineAppClassTime.self=7970339
sun.cls.defineAppClasses=4619
sun.cls.initializedClasses=5338
sun.cls.jniDefineClassNoLockCalls=0
sun.cls.jvmDefineClassNoLockCalls=1794
sun.cls.jvmFindLoadedClassNoLockCalls=18203
sun.cls.linkedClasses=6048
sun.cls.loadedBytes=11890424
sun.cls.lookupSysClassTime=0
sun.cls.methodBytes=5312960
sun.cls.nonSystemLoaderLockContentionRate=392
sun.cls.sharedClassLoadTime=214537
sun.cls.sharedLoadedBytes=2813104
sun.cls.sharedUnloadedBytes=0
sun.cls.sysClassBytes=3238173
sun.cls.sysClassLoadTime=1057911
sun.cls.systemLoaderLockContentionRate=1
sun.cls.time=41997312
sun.cls.unloadedBytes=0
sun.cls.unsafeDefineClassCalls=0
sun.cls.verifiedClasses=3903
sun.gc.cause="No GC"
sun.gc.collector.0.invocations=12
sun.gc.collector.0.lastEntryTime=84340969
sun.gc.collector.0.lastExitTime=84370245
sun.gc.collector.0.name="G1 young collection pauses"
sun.gc.collector.0.time=621407
sun.gc.collector.1.invocations=0
sun.gc.collector.1.lastEntryTime=0
sun.gc.collector.1.lastExitTime=0
sun.gc.collector.1.name="G1 full collection pauses"
sun.gc.collector.1.time=0
sun.gc.collector.2.invocations=4
sun.gc.collector.2.lastEntryTime=81517971
sun.gc.collector.2.lastExitTime=81518369
sun.gc.collector.2.name="G1 concurrent cycle pauses"
sun.gc.collector.2.time=153333
sun.gc.compressedclassspace.capacity=4456448
sun.gc.compressedclassspace.maxCapacity=1073741824
sun.gc.compressedclassspace.minCapacity=0
sun.gc.compressedclassspace.used=4222096
sun.gc.generation.0.agetable.bytes.00=0
sun.gc.generation.0.agetable.bytes.01=527312
sun.gc.generation.0.agetable.bytes.02=866968
sun.gc.generation.0.agetable.bytes.03=0
sun.gc.generation.0.agetable.bytes.04=0
sun.gc.generation.0.agetable.bytes.05=0
sun.gc.generation.0.agetable.bytes.06=0
sun.gc.generation.0.agetable.bytes.07=0
sun.gc.generation.0.agetable.bytes.08=0
sun.gc.generation.0.agetable.bytes.09=0
sun.gc.generation.0.agetable.bytes.10=0
sun.gc.generation.0.agetable.bytes.11=0
sun.gc.generation.0.agetable.bytes.12=0
sun.gc.generation.0.agetable.bytes.13=0
sun.gc.generation.0.agetable.bytes.14=0
sun.gc.generation.0.agetable.bytes.15=0
sun.gc.generation.0.agetable.size=16
sun.gc.generation.0.capacity=23068696
sun.gc.generation.0.maxCapacity=4259315736
sun.gc.generation.0.minCapacity=24
sun.gc.generation.0.name="young"
sun.gc.generation.0.space.0.capacity=20971528
sun.gc.generation.0.space.0.initCapacity=14680072
sun.gc.generation.0.space.0.maxCapacity=4259315720
sun.gc.generation.0.space.0.name="eden"
sun.gc.generation.0.space.0.used=10485760
sun.gc.generation.0.space.1.capacity=8
sun.gc.generation.0.space.1.initCapacity=8
sun.gc.generation.0.space.1.maxCapacity=8
sun.gc.generation.0.space.1.name="s0"
sun.gc.generation.0.space.1.used=0
sun.gc.generation.0.space.2.capacity=2097160
sun.gc.generation.0.space.2.initCapacity=8
sun.gc.generation.0.space.2.maxCapacity=4259315720
sun.gc.generation.0.space.2.name="s1"
sun.gc.generation.0.space.2.used=1530984
sun.gc.generation.0.spaces=3
sun.gc.generation.1.capacity=27262984
sun.gc.generation.1.maxCapacity=4259315720
sun.gc.generation.1.minCapacity=8
sun.gc.generation.1.name="old"
sun.gc.generation.1.space.0.capacity=27262984
sun.gc.generation.1.space.0.initCapacity=251658248
sun.gc.generation.1.space.0.maxCapacity=4259315720
sun.gc.generation.1.space.0.name="space"
sun.gc.generation.1.space.0.used=16948224
sun.gc.generation.1.spaces=1
sun.gc.lastCause="G1 Evacuation Pause"
sun.gc.metaspace.capacity=38715392
sun.gc.metaspace.maxCapacity=1109393408
sun.gc.metaspace.minCapacity=0
sun.gc.metaspace.used=38065224
sun.gc.policy.collectors=1
sun.gc.policy.desiredSurvivorSize=2097152
sun.gc.policy.gcTimeLimitExceeded=0
sun.gc.policy.generations=2
sun.gc.policy.maxTenuringThreshold=15
sun.gc.policy.name="GarbageFirst"
sun.gc.policy.tenuringThreshold=2
sun.gc.tlab.alloc=2338782
sun.gc.tlab.allocThreads=2
sun.gc.tlab.fastWaste=0
sun.gc.tlab.fills=70
sun.gc.tlab.gcWaste=485
sun.gc.tlab.maxFastWaste=0
sun.gc.tlab.maxFills=69
sun.gc.tlab.maxGcWaste=485
sun.gc.tlab.maxSlowAlloc=0
sun.gc.tlab.maxSlowWaste=5738
sun.gc.tlab.slowAlloc=0
sun.gc.tlab.slowWaste=5738
sun.os.hrt.frequency=10000000
sun.os.hrt.ticks=5052883243
sun.perfdata.majorVersion=2
sun.perfdata.minorVersion=0
sun.perfdata.overflow=0
sun.perfdata.size=65536
sun.perfdata.timestamp=637560
sun.perfdata.used=13968
sun.property.sun.boot.library.path="C:\java\java15\bin"
sun.rt._sync_ContendedLockAttempts=411
sun.rt._sync_Deflations=22
sun.rt._sync_FutileWakeups=167
sun.rt._sync_Inflations=24
sun.rt._sync_MonExtant=2
sun.rt._sync_Notifications=16
sun.rt._sync_Parks=570
sun.rt.applicationTime=318442617000
sun.rt.createVmBeginTime=1601599482552
sun.rt.createVmEndTime=1601599482604
sun.rt.internalVersion="Java HotSpot(TM) 64-Bit Server VM (15+36-1562) for windows-amd64 JRE (15+36-1562), built on Aug 11 2020 22:38:02 by "mach5one" with unknown MS VC++:1925"
sun.rt.javaCommand="org.springframework.boot.loader.JarLauncher run hello.groovy -- --server.port=8888"
sun.rt.jvmCapabilities="1100000000000000000000000000000000000000000000000000000000000000"
sun.rt.jvmVersion=251658276
sun.rt.safepointSyncTime=948600
sun.rt.safepointTime=83370900
sun.rt.safepoints=32
sun.rt.vmInitDoneTime=1601599482583
sun.threads.vmOperationTime=864168
sun.urlClassLoader.readClassBytesTime=464820000
sun.zip.zipFile.openTime=2215169600
sun.zip.zipFiles=12173

Как видите, много счетчиков, рассказывающих о поведении JIT-компилятора (sun.ci), загрузчика классов (sun.cls), сборщика мусора (sun.gc), среды исполнения (sun.rt) и прочее.

Остальные команды

Пройдемся по остальным важным командам:

VM.version — выдаст сигнатуру версии JVM

$jcmd
17316 
VM.version 17316: Java HotSpot(TM) 64-Bit Server VM version 15+36-1562 JDK 15.0.0

VM.flags — выдаст список параметров с которыми была запущена JVM

$jcmd 17316 VM.flags
17316: 
-XX:CICompilerCount=3 -XX:ConcGCThreads=1 -XX:G1ConcRefinementThreads=4 -XX:G1HeapRegionSize=2097152 -XX:GCDrainStackTargetSize=64 -XX:InitialHeapSize=266338304 -XX:MarkStackSize=4194304 -XX:MaxHeapSize=4259315712 -XX:MaxNewSize=2554331136 -XX:MinHeapDeltaBytes=2097152 -XX:MinHeapSize=8388608 -XX:NonNMethodCodeHeapSize=5832780 -XX:NonProfiledCodeHeapSize=122912730 -XX:ProfiledCodeHeapSize=122912730 -XX:ReservedCodeCacheSize=251658240 -XX:+SegmentedCodeCache -XX:SoftMaxHeapSize=4259315712 -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseFastUnorderedTimeStamps -XX:+UseG1GC -XX:-UseLargePagesIndividualAllocation

VM.info — замена утилиты jinfo. Выдаст обширнейшую информацию о JVM-процессе: карту памяти, загруженные библиотеки, характеристики процессора, процесса и heap, переменные среды окружения, и прочее.

VM.command_line — выдаст список параметров командной строки, с которыми была запущена JVM:

$jcmd 4244 VM.command_line
4244:
VM Arguments:
java_command: org.springframework.boot.loader.JarLauncher run hello.groovy -- --server.port=8888
java_class_path (initial): D:\tools\spring-cli\bin\..\lib\spring-boot-cli-2.3.3.RELEASE.jar
Launcher Type: SUN_STANDARD

VM.flags — выдаст всех флагов, с которыми запущена JVM. Помогает определить, точно ли переданы JVM все значения из командной строки, которые вы задали.

$jcmd 4244 VM.flags
4244:
-XX:CICompilerCount=3 -XX:ConcGCThreads=1 -XX:G1ConcRefinementThreads=4 -XX:G1HeapRegionSize=2097152 -XX:GCDrainStackTargetSize=64 -XX:InitialHeapSize=266338304 -XX:MarkStackSize=4194304 -XX:MaxHeapSize=4259315712 -XX:MaxNewSize=2554331136 -XX:MinHeapDeltaBytes=2097152 -XX:MinHeapSize=8388608 -XX:NonNMethodCodeHeapSize=5832780 -XX:NonProfiledCodeHeapSize=122912730 -XX:ProfiledCodeHeapSize=122912730 -XX:ReservedCodeCacheSize=251658240 -XX:+SegmentedCodeCache -XX:SoftMaxHeapSize=4259315712 -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseFastUnorderedTimeStamps -XX:+UseG1GC -XX:-UseLargePagesIndividualAllocation

VM.uptime — время прошедшее с момента запуска приложения в секундах:

$jcmd 4244 VM.uptime
4244:
273.204 s

VM.system_properties — выведет полный список всех системных свойств окружения JVM:

$jcmd 4244 VM.system_properties
4244: 
Fri Oct 02 19:46:54 GMT+09:00 2020 
java.specification.version=15
sun.cpu.isalist=amd64
sun.jnu.encoding=Cp1252
java.class.path=D\:\tools\spring-cli\bin\\..\lib\spring-boot-cli-2.3.3.RELEASE.jar
java.vm.vendor=Oracle Corporation
sun.arch.data.model=64
user.variant=
catalina.useNaming=false
java.vendor.url=https\://java.oracle.com/
user.timezone=GMT+09\:00
os.name=Windows 10
java.vm.specification.version=15
sun.java.launcher=SUN_STANDARD
user.country=US

...

java.vm.info=mixed mode, sharing
java.vendor=Oracle Corporation
java.vm.version=15+36-1562
sun.io.unicode.encoding=UnicodeLittle
java.class.version=59.0

GC.heap_info — выдаст текущие размеры heap, заодно покажет и какой сборщик мусора включен в JVM:

$jcmd 4244 GC.heap_info
4244:
garbage-first heap total 69632K, used 30555K [0x0000000702200000, 0x0000000800000000)
region size 2048K, 8 young (16384K), 1 survivors (2048K)
Metaspace used 38091K, capacity 38629K, committed 38704K, reserved 1083392K
class space used 4219K, capacity 4406K, committed 4480K, reserved 1048576K

Flight Recorder

Flight Recorder — это мощный инструмент встроенный в JVM, позовляющий вести запись всех параметров работы JVM в реальном времени и сохранять их в файл точно так же, как это делает настоящий «черный ящик» в самолете, записывающий все параметры полета. Раньше этот инструмент был коммерческим и включался параметром-ключом:

-XX:+UnlockCommercialFeatures

Но теперь этот модуль является бесплатным, и ключ не требуется. Запускать Flight Recorder можно сразу с запуском приложения с помощью параметра:

$java -XX:+FlightRecorder MyApp

а можно просто запустить приложение и включить Flight Recorder позже с помощью jcmd, причем его можно включать и выключать с помощью jcmd несколько раз, например, для снятия замеров в какие-то наиболее интересные моменты работы приложения.

JFR.start — запускает запись, а JFR.stop — останавливает ее. JFR.dump — позволяет сделать дамп записи в файл, который затем можно просмотреть утилитой Java Mission Control.

Выводы

Утилита jcmd является главным и незаменимым инструментом в jdk для снятия всех замеров с работающего Java-приложения. Эту утилиту можно вызывать из командной строки с различными параметрами с помощью, например, cron через определенные промежутки времени и получать «снимки» работающего Java-приложения, по которым можно потом судить, как ведет себя Java-приложение в различные моменты времени.


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

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

Логотип WordPress.com

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

Google photo

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

Фотография Twitter

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

Фотография Facebook

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

Connecting to %s