これは、なにをしたくて書いたもの？
Javaアプリケーションの状態を簡単に見る時に、自分が使うツールのひとつにjstatがあります。
このjstatコマンドですが、jcmdに直接の代替がなく、いつもjstatはjstatのままだったのですが。
jcmdのPerfCounter.printから同じような結果が得られそうだったので、コマンドっぽいものを作ってみることにしました。
jcmdのPerfCounter.print
jcmdのドキュメントはこちら。
jcmdにpidのみを指定すると、使用できるコマンドが表示されます。
$ jcmd [pid] 28597: 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.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 JFR.view JVMTI.agent_load JVMTI.data_dump ManagementAgent.start ManagementAgent.start_local ManagementAgent.status ManagementAgent.stop System.native_heap_info System.trim_native_heap Thread.dump_to_file Thread.print VM.cds VM.class_hierarchy VM.classes VM.classloader_stats VM.classloaders VM.command_line VM.dynlibs VM.events VM.flags VM.info VM.log VM.metaspace VM.native_memory 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 <command>'.
これがヘルプ的な意味合いにもなっているのですが。
ここに表示されないコマンドとしてPerfCounter.printがあります。
jcmdのヘルプにも、確かに出てきます。
$ jcmd -h Usage: jcmd <pid | main class> <command ...|PerfCounter.print|-f file> or: jcmd -l or: jcmd -h command must be a valid jcmd command for the selected jvm. Use the command "help" to see which commands are available. If the pid is 0, commands will be sent to all Java processes. The main class argument will be used to match (either partially or fully) the class used to start Java. If no options are given, lists Java processes (same as -l). PerfCounter.print display the counters exposed by this process -f read and execute commands from the file -l list JVM processes on the local machine -? -h --help print this help message
実行結果のサンプルはこんな感じです。
$ jcmd 28597 PerfCounter.print 28597: java.ci.totalTime=8647986132 java.cls.loadedClasses=10311 java.cls.sharedLoadedClasses=1291 java.cls.sharedUnloadedClasses=0 java.cls.unloadedClasses=67 java.property.java.class.path="/path/to/wildfly-31.0.0.Final/jboss-modules.jar" java.property.java.home="/usr/lib/jvm/java-21-openjdk-amd64" java.property.java.library.path="/usr/java/packages/lib:/usr/lib/x86_64-linux-gnu/jni:/lib/x86_64-linux-gnu:/usr/lib/x86_64-linux-gnu:/usr/lib/jni:/lib:/usr/lib" java.property.java.version="21.0.1" java.property.java.vm.info="mixed mode, sharing" java.property.java.vm.name="OpenJDK 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="21" java.property.java.vm.vendor="Private Build" java.property.java.vm.version="21.0.1+12-Ubuntu-222.04" java.property.jdk.debug="release" java.rt.vmArgs="-D[Standalone] -Djdk.serialFilter=maxbytes=10485760;maxdepth=128;maxarray=100000;maxrefs=300000 -Xms64m -Xmx512m -XX:MetaspaceSize=96M -XX:MaxMetaspaceSize=256m -Djava.net.preferIPv4Stack=true -Djboss.modules.system.pkgs=org.jboss.byteman -Djava.awt.headless=true --add-exports=java.desktop/sun.awt=ALL-UNNAMED --add-exports=java.naming/com.sun.jndi.ldap=ALL-UNNAMED --add-exports=java.naming/com.sun.jndi.url.ldap=ALL-UNNAMED --add-exports=java.naming/com.sun.jndi.url.ldaps=ALL-UNNAMED --add-exports=jdk.naming.dns/com.sun.jndi.dns=ALL-UNNAMED --add-opens=java.base/java.lang=ALL-UNNAMED --add-opens=java.base/java.lang.invoke=ALL-UNNAMED --add-opens=java.base/java.lang.reflect=ALL-UNNAMED --add-opens=java.base/java.io=ALL-UNNAMED --add-opens=java.base/java.net=ALL-UNNAMED --add-opens=java.base/java.security=ALL-UNNAMED --add-opens=java.base/java.util=ALL-UNNAMED --add-opens=java.base/java.util.concurrent=ALL-UNNAMED --add-opens=java.management/javax.management=ALL-UNNAMED --add-opens=java.naming/javax.naming=ALL-U" java.rt.vmFlags="" java.threads.daemon=14 java.threads.live=53 java.threads.livePeak=127 java.threads.started=130 sun.ci.findWitnessAnywhere=5384 sun.ci.findWitnessAnywhereSteps=71042 sun.ci.findWitnessIn=1110 sun.ci.lastFailedMethod="" sun.ci.lastFailedType=0 sun.ci.lastInvalidatedMethod="" sun.ci.lastInvalidatedType=0 sun.ci.lastMethod="org/jboss/as/controller/AbstractOperationContext$Step matches" sun.ci.lastSize=11 sun.ci.lastType=1 sun.ci.nmethodBucketsAllocated=2514 sun.ci.nmethodBucketsDeallocated=315 sun.ci.nmethodBucketsStale=315 sun.ci.nmethodBucketsStaleAccumulated=315 sun.ci.nmethodCodeSize=7027760 sun.ci.nmethodSize=10136288 sun.ci.osrBytes=33922 sun.ci.osrCompiles=51 sun.ci.osrTime=921796991 sun.ci.standardBytes=627358 sun.ci.standardCompiles=4990 sun.ci.standardTime=7726189141 sun.ci.threads=4 sun.ci.totalBailouts=0 sun.ci.totalCompiles=5041 sun.ci.totalInvalidates=0 sun.classloader.findClassTime=0 sun.classloader.findClasses=0 sun.classloader.parentDelegationTime=0 sun.cls.appClassBytes=32115423 sun.cls.appClassLoadCount=17026 sun.cls.appClassLoadTime=8358453921 sun.cls.appClassLoadTime.self=5258384601 sun.cls.classInitTime=4856071961 sun.cls.classInitTime.self=2834755142 sun.cls.classLinkedTime=4185116976 sun.cls.classLinkedTime.self=950032300 sun.cls.classVerifyTime=3233879597 sun.cls.classVerifyTime.self=724386141 sun.cls.defineAppClassTime=4394064669 sun.cls.defineAppClassTime.self=2905079418 sun.cls.defineAppClasses=7661 sun.cls.initializedClasses=9236 sun.cls.linkedClasses=10253 sun.cls.loadedBytes=19410120 sun.cls.lookupSysClassTime=0 sun.cls.methodBytes=7269302 sun.cls.sharedClassLoadTime=5221732 sun.cls.sharedLoadedBytes=3159208 sun.cls.sharedUnloadedBytes=0 sun.cls.sysClassBytes=6109993 sun.cls.sysClassLoadTime=7965134472 sun.cls.time=12668645866 sun.cls.unloadedBytes=67960 sun.cls.unsafeDefineClassCalls=0 sun.cls.verifiedClasses=7198 sun.gc.cause="No GC" sun.gc.collector.0.invocations=14 sun.gc.collector.0.lastEntryTime=2188733252661 sun.gc.collector.0.lastExitTime=2188740921796 sun.gc.collector.0.name="G1 young collection pauses" sun.gc.collector.0.time=80863513 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=6 sun.gc.collector.2.lastEntryTime=2188824411961 sun.gc.collector.2.lastExitTime=2188824543216 sun.gc.collector.2.name="G1 concurrent cycle pauses" sun.gc.collector.2.time=13452919 sun.gc.compressedclassspace.capacity=7995392 sun.gc.compressedclassspace.maxCapacity=218103808 sun.gc.compressedclassspace.minCapacity=0 sun.gc.compressedclassspace.used=7180424 sun.gc.generation.0.agetable.bytes.00=0 sun.gc.generation.0.agetable.bytes.01=15184 sun.gc.generation.0.agetable.bytes.02=0 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=41943040 sun.gc.generation.0.maxCapacity=536870912 sun.gc.generation.0.minCapacity=0 sun.gc.generation.0.name="young" sun.gc.generation.0.space.0.capacity=40894464 sun.gc.generation.0.space.0.initCapacity=24117248 sun.gc.generation.0.space.0.maxCapacity=536870912 sun.gc.generation.0.space.0.name="eden" sun.gc.generation.0.space.0.used=4194304 sun.gc.generation.0.space.1.capacity=0 sun.gc.generation.0.space.1.initCapacity=0 sun.gc.generation.0.space.1.maxCapacity=0 sun.gc.generation.0.space.1.name="s0" sun.gc.generation.0.space.1.used=0 sun.gc.generation.0.space.2.capacity=1048576 sun.gc.generation.0.space.2.initCapacity=0 sun.gc.generation.0.space.2.maxCapacity=536870912 sun.gc.generation.0.space.2.name="s1" sun.gc.generation.0.space.2.used=511280 sun.gc.generation.0.spaces=3 sun.gc.generation.1.capacity=65011712 sun.gc.generation.1.maxCapacity=536870912 sun.gc.generation.1.minCapacity=0 sun.gc.generation.1.name="old" sun.gc.generation.1.space.0.capacity=65011712 sun.gc.generation.1.space.0.initCapacity=42991616 sun.gc.generation.1.space.0.maxCapacity=536870912 sun.gc.generation.1.space.0.name="space" sun.gc.generation.1.space.0.used=51193256 sun.gc.generation.1.spaces=1 sun.gc.lastCause="G1 Evacuation Pause" sun.gc.metaspace.capacity=56885248 sun.gc.metaspace.maxCapacity=285212672 sun.gc.metaspace.minCapacity=0 sun.gc.metaspace.used=54701496 sun.gc.policy.collectors=1 sun.gc.policy.desiredSurvivorSize=2621440 sun.gc.policy.gcTimeLimitExceeded=0 sun.gc.policy.generations=2 sun.gc.policy.maxTenuringThreshold=15 sun.gc.policy.name="GarbageFirst" sun.gc.policy.tenuringThreshold=1 sun.gc.tlab.alloc=4451453 sun.gc.tlab.allocThreads=10 sun.gc.tlab.fills=2355 sun.gc.tlab.gcWaste=19426 sun.gc.tlab.maxFills=2208 sun.gc.tlab.maxGcWaste=7819 sun.gc.tlab.maxRefillWaste=164549 sun.gc.tlab.maxSlowAlloc=58 sun.gc.tlab.refillWaste=174876 sun.gc.tlab.slowAlloc=58 sun.os.hrt.frequency=1000000000 sun.os.hrt.ticks=2385024412405 sun.perfdata.majorVersion=2 sun.perfdata.minorVersion=0 sun.perfdata.overflow=0 sun.perfdata.size=32768 sun.perfdata.timestamp=37415726 sun.perfdata.used=14176 sun.property.sun.boot.library.path="/usr/lib/jvm/java-21-openjdk-amd64/lib" sun.rt._sync_ContendedLockAttempts=294 sun.rt._sync_Deflations=105 sun.rt._sync_FutileWakeups=38 sun.rt._sync_Inflations=112 sun.rt._sync_MonExtant=7 sun.rt._sync_Notifications=40 sun.rt._sync_Parks=318 sun.rt.applicationTime=2188101694928 sun.rt.createVmBeginTime=1708262503876 sun.rt.createVmEndTime=1708262503909 sun.rt.internalVersion="OpenJDK 64-Bit Server VM (21.0.1+12-Ubuntu-222.04) for linux-amd64 JRE (21.0.1+12-Ubuntu-222.04), built on 2023-11-06T14:11:20Z by "buildd" with gcc 12.3.0" sun.rt.javaCommand="/path/to/wildfly-31.0.0.Final/jboss-modules.jar -mp /path/to/wildfly-31.0.0.Final/modules org.jboss.as.standalone -Djboss.home.dir=/path/to/wildfly-31.0.0.Final -Djboss.server.base.dir=/path/to/wildfly-31.0.0.Final/standalone" sun.rt.jvmCapabilities="1100000000000000000000000000000000000000000000000000000000000000" sun.rt.jvmVersion=352321804 sun.rt.safepointSyncTime=610642459 sun.rt.safepointTime=99351508 sun.rt.safepoints=109 sun.rt.vmInitDoneTime=1708262503893 sun.threads.vmOperationTime=172142435 sun.urlClassLoader.readClassBytesTime=0 sun.zip.zipFile.openTime=497130199 sun.zip.zipFiles=1203
それなりにたくさん出てきて、1回表示されてコマンドが終了します。
PerfCounter.printの説明には、以下のように書かれています。
指定されたJavaプロセスによって公開されるパフォーマンス・カウンタを出力します。
パフォーマンス・カウンタを単発で取得するコマンド、というわけです。
この内容をあまり細かく見ていなかったのですが、jstatの出力結果とそれなり重なっていることに気づいたのがこのエントリーを
書こうと思ったきっかけです。
ちなみにPerfCounter.printは完全に特別扱いされていて、コマンドとしてPerfCounter.printを与えるとカウンタをリストアップするように
フラグが立ち
PerfCounter.print専用の動作になります。
jstatとjcmdで取得できるパフォーマンス・カウンタ
jstatのソースコードはこちらです。
中身を見ると統計情報自体を扱っている処理はほぼなく、その内容はsun.jvmstat.monitorパッケージに依存していることになります。
そしてここでjcmdのPerfCounter.printの実装箇所を見ると、似たような内容が並んでいます。
使っているのは同じsun.jvmstat.monitorパッケージですし、なんならjstat関連のクラスも使っています。
import sun.tools.jstat.JStatLogger; import sun.jvmstat.monitor.Monitor; import sun.jvmstat.monitor.MonitoredHost; import sun.jvmstat.monitor.MonitoredVm; import sun.jvmstat.monitor.MonitorException; import sun.jvmstat.monitor.VmIdentifier;
となると、同じような情報が取得できているのでは？と思って見ていたら、こんな定義を見つけました。
jstatのオプション定義で、各オプションに対してどのような内容が出力されるのかがこちらに定義されています。
一方でjcmdでのパフォーマンス・カウンタの定義とエイリアスはこちらに定義されています。
この両者を見比べると、マッピングができそうです。
たとえば、jstatの-gcオプションで取得できる項目にS0C（Survivor領域0の現在の容量(KB)）があります。
option gc {
column {
header "^S0C^" /* Survivor 0 Space Capacity - Current */
data sun.gc.generation.0.space.1.capacity
scale K
align right
width 11
format "0.0"
}
dataの部分がカウンタ名で、こちらはjcmd側でも確認できます。
alias sun.gc.generation.0.space.1.capacity // 1.5.0 b39
hotspot.gc.generation.0.space.1.capacity // 1.4.2
hotspot.gc.new.s0.capacity // 1.4.1
これで読み替えていけそうですね。
今回は、jcmdのPerfCounter.printで取得できるパフォーマンス・カウンタの値をjstatのヘッダーの名前に読み替えてjstatっぽく
出力するスクリプトを書いてみたいと思います。
ここでJavaを使うと意味がない感じがするので、Pythonで書くことにしましょう。
環境
今回の環境はこちら。
$ python3 --version Python 3.10.12 $ java --version openjdk 21.0.1 2023-10-17 OpenJDK Runtime Environment (build 21.0.1+12-Ubuntu-222.04) OpenJDK 64-Bit Server VM (build 21.0.1+12-Ubuntu-222.04, mixed mode, sharing)
Javaはスクリプトには関係ないのですが、jcmdとJavaアプリケーションの実行に使用しました。
なお、スクリプトの実行先にするJavaアプリケーションはWildFly 31.0.0.Finalとしました。が、こちらについてはこれ以上触れません。
スクリプト
作成したスクリプトはこちら。
jstat.py
import re import subprocess import sys import time interest_metrics = { "sun.gc.generation.0.space.1.capacity": "S0C", "sun.gc.generation.0.space.2.capacity": "S1C", "sun.gc.generation.0.space.1.used": "S0U", "sun.gc.generation.0.space.2.used": "S1U", "sun.gc.generation.0.space.0.capacity": "EC", "sun.gc.generation.0.space.0.used": "EU", "sun.gc.generation.1.space.0.capacity": "OC", "sun.gc.generation.1.space.0.used": "OU", "sun.gc.metaspace.capacity": "MC", "sun.gc.metaspace.used": "MU", "sun.gc.compressedclassspace.capacity": "CCSC", "sun.gc.compressedclassspace.used": "CCSU", "sun.gc.collector.0.invocations": "YGC", "sun.gc.collector.1.invocations": "FGC", "sun.gc.collector.2.invocations": "CGC" # GCT系は計算しているので除外 } names = [name for name in interest_metrics.keys()] header = [alias for alias in interest_metrics.values()] def to_metrics(text): return { f"{line.split('=')[0]}": line.split("=")[1] for line in text.splitlines() if re.fullmatch(r".+=.+", line) != None } pid = sys.argv[1] sleep_sec = float(sys.argv[2]) print("\t".join(header), flush=True) try: while True: perf_counter_result = subprocess.run(["jcmd", pid, "PerfCounter.print"], capture_output=True) perf_counter_stdout= perf_counter_result.stdout.decode("utf-8") metrics = to_metrics(perf_counter_stdout) values = [metrics[name] for name in names] print("\t".join(values), flush=True) time.sleep(sleep_sec) except KeyboardInterrupt: pass
実行例はこんな感じになります。
$ python3 jstat.py 28597 1 S0C S1C S0U S1U EC EU OC OU MC MU CCSC CCSU YGC FGC CGC 0 1048576 0 148352 46137344 38797312 59768832 51193256 56885248 54724960 7995392 7180424 15 0 6 0 1048576 0 148352 46137344 38797312 59768832 51193256 56885248 54724960 7995392 7180424 15 0 6 0 1048576 0 148352 46137344 38797312 59768832 51193256 56885248 54724960 7995392 7180424 15 0 6 0 1048576 0 148352 46137344 38797312 59768832 51193256 56885248 54724960 7995392 7180424 15 0 6 0 1048576 0 148352 46137344 38797312 59768832 51193256 56885248 54724960 7995392 7180424 15 0 6
第1引数がpid、第2引数が出力間隔（秒）です。
取得対象のパフォーマンス・カウンタとヘッダーのマッピングは辞書で定義。
interest_metrics = {
"sun.gc.generation.0.space.1.capacity": "S0C",
"sun.gc.generation.0.space.2.capacity": "S1C",
"sun.gc.generation.0.space.1.used": "S0U",
"sun.gc.generation.0.space.2.used": "S1U",
"sun.gc.generation.0.space.0.capacity": "EC",
"sun.gc.generation.0.space.0.used": "EU",
"sun.gc.generation.1.space.0.capacity": "OC",
"sun.gc.generation.1.space.0.used": "OU",
"sun.gc.metaspace.capacity": "MC",
"sun.gc.metaspace.used": "MU",
"sun.gc.compressedclassspace.capacity": "CCSC",
"sun.gc.compressedclassspace.used": "CCSU",
"sun.gc.collector.0.invocations": "YGC",
"sun.gc.collector.1.invocations": "FGC",
"sun.gc.collector.2.invocations": "CGC"
# GCT系は計算しているので除外
}
YGCTなどの時間系のものは演算されていたので、今回は対象外にしました。
column {
header "^YGCT^" /* Young Generation Collection Time */
data sun.gc.collector.0.time/sun.os.hrt.frequency
align right
width 9
scale sec
format "0.000"
}
ここからパフォーマンス・カウンタ名とヘッダー名をリストに分離。
names = [name for name in interest_metrics.keys()] header = [alias for alias in interest_metrics.values()]
起動引数は、pidと出力間隔です。出力間隔はtime.sleepに渡すのでfloatでの指定を可にしています。
pid = sys.argv[1] sleep_sec = float(sys.argv[2])
あとは最初にヘッダーを出力して後に、time.sleepしつつjcmdを呼び出してその結果を表示します。
print("\t".join(header), flush=True) try: while True: perf_counter_result = subprocess.run(["jcmd", pid, "PerfCounter.print"], capture_output=True) perf_counter_stdout= perf_counter_result.stdout.decode("utf-8") metrics = to_metrics(perf_counter_stdout) values = [metrics[name] for name in names] print("\t".join(values), flush=True) time.sleep(sleep_sec) except KeyboardInterrupt: pass
パフォーマンス・カウンタの値は=で区切って辞書へ変換しています。
def to_metrics(text): return { f"{line.split('=')[0]}": line.split("=")[1] for line in text.splitlines() if re.fullmatch(r".+=.+", line) != None }
これで完成です。
オリジナルのjstatと比べてみましょう。
今回作成したスクリプト。
$ python3 jstat.py 28597 1 S0C S1C S0U S1U EC EU OC OU MC MU CCSC CCSU YGC FGC CGC 0 1048576 0 66456 53477376 1048576 52428800 46452608 56885248 54739248 7995392 7180424 16 0 6 0 1048576 0 66456 53477376 1048576 52428800 46452608 56885248 54739248 7995392 7180424 16 0 6 0 1048576 0 66456 53477376 1048576 52428800 46452608 56885248 54739248 7995392 7180424 16 0 6
jstat。
$ jstat -gc 28597 1000
S0C S1C S0U S1U EC EU OC OU MC MU CCSC CCSU YGC YGCT FGC FGCT CGC CGCT GCT
0.0 1024.0 0.0 64.9 52224.0 1024.0 51200.0 45363.9 55552.0 53456.3 7808.0 7012.1 16 0.093 0 0.000 6 0.013 0.107
0.0 1024.0 0.0 64.9 52224.0 1024.0 51200.0 45363.9 55552.0 53456.3 7808.0 7012.1 16 0.093 0 0.000 6 0.013 0.107
0.0 1024.0 0.0 64.9 52224.0 1024.0 51200.0 45363.9 55552.0 53456.3 7808.0 7012.1 16 0.093 0 0.000 6 0.013 0.107
YGCT、FGCT、GCTがないのはいいとして、ヒープの使用状況などの数字が違いますね。
これはjstat側は表示単位がKBになっているからです。
たとえばS0CではscaleがKになっていました。
option gc {
column {
header "^S0C^" /* Survivor 0 Space Capacity - Current */
data sun.gc.generation.0.space.1.capacity
scale K
align right
width 11
format "0.0"
}
というか、ほとんどがscale Kですが。
とりあえず、やりたいことはできたのかなと。
おわりに
jstatライクなコマンド（スクリプト）をjcmdのPerfCounter.printの結果から作ってみました。
ネタみたいなものですが、jcmdやjstatの実装内容などを追うことになったのでそれなりに得るものもありました。
jstatの元になっているjvmstat内で取得しているパフォーマンス・カウンタがどういう方法で値を見ているのかも知りたかったのですが、
ちょっと追い切れなかったので今回は諦めました。
まあ、いいかなと。
