通过 JFR 统计 Java 进程一段时间内的 CPU 利用率

本文介绍利用 https://github.com/jvm-profiling-tools/async-profiler 采集 JFR 格式文件，统计 JVM 进程的 CPU 使用率。

采集进程信息为 JFR 文件

方式一：对已在运行的 JVM 进程采样

通过 jps -l 查看对应 JVM 进程 PID：

% jps -l
182403 org.gradle.launcher.daemon.bootstrap.GradleDaemon
218726 org.jetbrains.jps.cmdline.Launcher
218132 org.apache.shardingsphere.proxy.Bootstrap
220138 jdk.jcmd/sun.tools.jps.Jps
52986 
218111 org.jetbrains.jps.cmdline.Launcher
10124 org.jetbrains.idea.maven.server.RemoteMavenServer36
176222 org.apache.zookeeper.server.quorum.QuorumPeerMain
9837 com.intellij.idea.Main
176223 org.apache.zookeeper.server.quorum.QuorumPeerMain
176221 org.apache.zookeeper.server.quorum.QuorumPeerMain

执行 async-profiler 采样：

./profiler.sh -d 60 -e cpu,lock -i 100ms --lock 10ms -f ~/profiling/proxy-og-%t.jfr 218132

其中：

• -d 指采样时长，60 即 60 秒
• -e 指采集的事件，至少需要有 cpu
• -i 指 cpu 采样间隔，默认 10ms，间隔设置 10ms 以上几乎对进程本身性能没有影响
• -f 指 JFR 文件输出路径，%t 会自动替换成日期时间，文件名结尾 .jfr 则记录为 JFR 格式文件
• 最后的参数是 JVM 进程 PID

详细参数列表可以参考：https://github.com/jvm-profiling-tools/async-profiler#profiler-options

待采样完成后，得到 jfr 格式文件。

% ./profiler.sh -d 60 -e cpu,lock -i 100ms --lock 10ms -f ~/profiling/proxy-og-%t.jfr 218132
Profiling for 60 seconds
Done

方式二：启动 JVM 进程时增加 async-profiler Agent

启动 JVM 进程的时候，可以加入 async-profiler 的 Agent：

java -agentpath:/path/to/libasyncProfiler.so=start,event=cpu,alloc=2m,lock=10ms,file=profile.jfr

参数列表可以参考：https://github.com/jvm-profiling-tools/async-profiler/blob/v2.7/src/arguments.cpp#L52

通过 jfr 获取 CPULoad 事件

假设我们采样所得文件名为 proxy-og-20220424-162745.jfr。通过 JDK 自带的命令 jfr 可以读取 jfr 文件信息。

执行以下命令可以列出 JFR 文件中的事件列表：

jfr summary proxy-og-20220424-162745.jfr

 Version: 2.0
 Chunks: 1
 Start: 2022-04-24 08:27:45 (UTC)
 Duration: 60 s

 Event Type                          Count  Size (bytes) 
=========================================================
 jdk.ExecutionSample                  2473         38906
 jdk.CPULoad                            60          1260
 jdk.NativeLibrary                      28          1996
 jdk.ActiveSetting                      22           744
 jdk.InitialSystemProperty              22          9554
 jdk.Metadata                            1          5954
 jdk.CheckPoint                          1        368913
 jdk.ActiveRecording                     1            79
 jdk.OSInformation                       1           103
 jdk.CPUInformation                      1           367
 jdk.JVMInformation                      1           742
 jdk.ObjectAllocationInNewTLAB           0             0
 jdk.ObjectAllocationOutsideTLAB         0             0
 jdk.JavaMonitorEnter                    0             0
 jdk.ThreadPark                          0             0
 profiler.Log                            0             0

其中，jdk.CPULoad 就是我们所需要的 CPU 使用率。
通过以下命令可以获取到 CPULoad 事件的详细信息：

jfr print --events CPULoad proxy-og-20220424-162745.jfr | head -14

默认输出格式如下：

jdk.CPULoad {
  startTime = 2022-04-24T08:27:47.007953629Z
  jvmUser = 0.49240655
  jvmSystem = 0.033878505
  machineTotal = 0.9892409
}

jdk.CPULoad {
  startTime = 2022-04-24T08:27:48.008324647Z
  jvmUser = 0.525
  jvmSystem = 0.034375
  machineTotal = 0.98707175
}

可以通过 --xml 输出如下格式：

<?xml version="1.0" encoding="UTF-8"?>
<recording xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance">
  <events>
    <event type="jdk.CPULoad">
      <value name="startTime">2022-04-24T08:27:47.007953629Z</value>
      <value name="jvmUser">0.49240655</value>
      <value name="jvmSystem">0.033878505</value>
      <value name="machineTotal">0.9892409</value>
    </event>

    <event type="jdk.CPULoad">
      <value name="startTime">2022-04-24T08:27:48.008324647Z</value>
      <value name="jvmUser">0.525</value>
      <value name="jvmSystem">0.034375</value>
      <value name="machineTotal">0.98707175</value>
    </event>    
  </events>
</recording>

或者通过 --json 输出如下格式：

{
  "recording": {
    "events": [{
      "type": "jdk.CPULoad", 
      "values": {
        "startTime": "2022-04-24T08:27:47.007953629Z", 
        "jvmUser": 0.49240655, 
        "jvmSystem": 0.033878505, 
        "machineTotal": 0.9892409
      }
    }, {
      "type": "jdk.CPULoad", 
      "values": {
        "startTime": "2022-04-24T08:28:46.026037196Z", 
        "jvmUser": 0.155, 
        "jvmSystem": 0.088125, 
        "machineTotal": 0.9093937
      }
    }]
  }
}

统计

统计方面，我们可以借助 awk 工具简单统计，例如累加所有 CPU 使用率百分比：

jfr print --events CPULoad proxy-og-20220424-162745.jfr | awk '/jvmUser/ { us += $3; jvm += $3 } ; /jvmSystem/ { sy += $3; jvm += $3 } ; /machineTotal/ { total += $3 }  END { print "JVM us:",us,"\nJVM sy:",sy,"\nJVM total:",jvm,"\nMachine Total:",total }'

得到结果：

JVM us: 10.9825 
JVM sy: 5.47018 
JVM total: 16.4527 
Machine Total: 55.1735

每秒 CPU 使用率数据已经有了，可以根据自己的需求进行其他统计。