Abstract

在这篇文章中我们会综合性的介绍如何监控JVM cpu, thread 级别cpu, 以及如何通过JFR技术来分析JVM的CPU 问题.

如何获取CPU

这里我们会先介绍如何在进程内部获取JVM的CPU. 这里我们主要采用JVM 自带的JMX来实现对自己的监控.

获取整个系统的JVM cpu

可以通过调用mbean中的getProcessCpuTime方法来得到中的cputime.

简单点来说就是:

(cputime2 - cputime1)/1000000/elapseTimeInMs/processorCount

完整代码如下:

package cpu;import com.sun.management.OperatingSystemMXBean;import java.lang.management.ManagementFactory;
import java.util.concurrent.Executors;
import java.util.concurrent.ScheduledExecutorService;
import java.util.concurrent.ThreadFactory;
import java.util.concurrent.TimeUnit;
import java.util.concurrent.atomic.AtomicInteger;public class CpuTest {public static void main(String[] args) {final AtomicInteger seq = new AtomicInteger(0);ScheduledExecutorService es = Executors.newScheduledThreadPool(20, new ThreadFactory() {@Overridepublic Thread newThread(Runnable r) {Thread th = new Thread(r);th.setName("consumingthreads-" + seq.incrementAndGet());return th;}});for (int i = 0; i < 200; i++) {es.scheduleAtFixedRate(new ConsumingCpuTask(), 0, 10, TimeUnit.MILLISECONDS);}// not terminate the es// another thread to print host cpuScheduledExecutorService printer = Executors.newSingleThreadScheduledExecutor(new ThreadFactory() {@Overridepublic Thread newThread(Runnable r) {Thread th = new Thread(r);th.setName("printer");return th;}});// print every 10 secondsprinter.scheduleAtFixedRate(new PrintCurrentProcessCpuTask(), 0, 10, TimeUnit.SECONDS);}static final int PROCESSOR_COUNT = Runtime.getRuntime().availableProcessors();// notice here is com.sun.management.OperatingSystemMXBean and it's not java.lang.management.OperatingSystemMXBeanstatic final OperatingSystemMXBean bean = (OperatingSystemMXBean) ManagementFactory.getOperatingSystemMXBean();/*** get process cpu in nanoseconds*/static double getProcessCpuTime() {return bean.getProcessCpuTime();}/*** A task to simulate consuming cpu*/static class ConsumingCpuTask implements Runnable {@Overridepublic void run() {AtomicInteger integer = new AtomicInteger(0);for (int i = 0; i < 10000; i++) {integer.incrementAndGet();}}}static class PrintCurrentProcessCpuTask implements Runnable {double cpuTime = 0;long collectTime = 0;@Overridepublic void run() {if (cpuTime == 0) {cpuTime = getProcessCpuTime();collectTime = System.currentTimeMillis();}else {double newCpuTime = getProcessCpuTime();long newCollectTime = System.currentTimeMillis();double cpu = (newCpuTime - cpuTime) / (newCollectTime - collectTime) / 1000_000 / PROCESSOR_COUNT;cpuTime = newCpuTime;collectTime = newCollectTime;System.out.println(String.format("Process cpu is: %.2f %%", cpu * 100));}}}
}

当你运行这个代码就可以看到定时打出的cpu指标,比如在我的机器上是17%左右(本身有16核):

而这个值跟系统显示也是一致的(mac端的Activity Monitor/top命令):

或者用Java自带的Jconsole 可以看(是JDK自带的工具, 在bin目录),运行jconsole

选择关注的进程:

获取系统中各个线程的CPU

这里我们会展示如何获取系统中各个线程的CPU 这个也很好统计.

获取线程的cpu主要通过ThreadMXBean获取:

    // it's com.sun.management.ThreadMXBeanstatic ThreadMXBean threadMXBean = (ThreadMXBean) ManagementFactory.getThreadMXBean();static class PrintThreadCpuTask implements Runnable {// not consider thread safe hereMap<Long, Long> threadId2CpuTime = null;Map<Long, String> threadId2Name = null;private long collectTime = 0;@Overridepublic void run() {if (threadId2CpuTime == null) {threadId2CpuTime = new HashMap<>();threadId2Name = new HashMap<>();long threads[] = threadMXBean.getAllThreadIds();long cpuTimes[] = threadMXBean.getThreadCpuTime(threads);for (int i = 0; i < threads.length; i++) {threadId2CpuTime.put(threads[i], cpuTimes[i]);// get the thread name// maybe null, if not exists any moreThreadInfo info = threadMXBean.getThreadInfo(threads[i]);if (info != null) {threadId2Name.put(threads[i], info.getThreadName());}}collectTime = System.currentTimeMillis();}else {long threads[] = threadMXBean.getAllThreadIds();long cpuTimes[] = threadMXBean.getThreadCpuTime(threads);Map<Long, Long> newthreadId2CpuTime = new HashMap<>();for (int i = 0; i < threads.length; i++) {newthreadId2CpuTime.put(threads[i], cpuTimes[i]);}long newCollectTime = System.currentTimeMillis();threadId2CpuTime.entrySet().forEach(en -> {long threadId = en.getKey();Long time = en.getValue();Long newTime = newthreadId2CpuTime.get(threadId);if (newTime != null) {double cpu = (newTime - time) * 1.0d / (newCollectTime - collectTime) / 1000000L / PROCESSOR_COUNT;System.out.println(String.format("\t\tThread %s cpu is: %.2f %%", threadId2Name.get(threadId), cpu * 100));}threadId2CpuTime.put(threadId, newTime);});}}}

输出如下:

如何分析

什么JFR

JFR(Java flying recorder), 是java内置的一个性能数据采集器. 可以详细的获取JVM内部的状态和事件.

JFR分析示例

通过如下的命令激活JFR:

java -XX:+UnlockCommercialFeatures -XX:+FlightRecorder cpu.CpuTest

运行后通过内置的JCMD就可以进行采集等操作(JCMD 还有其他命令比如JFR.check 等.)

这个文件可以通过JMC(Java mission control)打开, 直接运行jmc即可 (也在jdk/bin下面):

在这里面就可以看到热点方法:

JFR本身还支持很多事件的采集包括GC/IO等.

Reference:https://docs.oracle.com/javacomponents/jmc-5-4/jfr-runtime-guide/about.htm

一个实际例子

在产品环境中发现的一个问题, 客户会周期的执行一些snmp数据采集任务集合A, 然后每隔一段时间又会执行另外的任务集合B(此时A也在同步执行), 发现此时B执行时, CPU比较高, 这是正常的因为任务B本身比较耗CPU, 但是发现任务B完成后, CPU依然很高, 并没有下降的趋势.

CPU图形如下:

1. 分析了任务A的成功率并没有变化.

2. 我们对比了前后的线程是否有增减, 找到了一个Windows selector 但是一查CPU 也没有明显的变化(~3%).

3. 最后我们用前面的脚本查询了前后两次的所有线程的CPU 发现了, snmp相关的线程cpu每个都从1.5% 增加到了 7%.

59 lm-collector-snmp-transport--4-1=1.61
60 lm-collector-snmp-transport--4-2=1.48
61 lm-collector-snmp-transport--4-3=1.56
62 lm-collector-snmp-transport--4-4=1.80
64 lm-collector-snmp-transport--4-5=1.64
65 snmp-selector=1.22
66 lm-collector-snmp-transport--4-6=1.41
67 lm-collector-snmp-transport--4-7=1.46
68 lm-collector-snmp-transport--4-10=1.77
69 lm-collector-snmp-transport--4-9=1.51
70 lm-collector-snmp-transport--4-8=1.88

4. 然后突然想起来了好像我们底层是共享的snmp 发送线程, 然后又因为有流控. 所以总共10组线程会每隔10ms 做一个host的发送任务. 但是在任务B中我们新加进来了很多任务(每个host新加了一个任务,然后在这10个线程中),相当于以前有900个host, 我们的线程组就会: 每10ms 执行900 次任务了, 然后B任务执行时, 又加了900个任务进来就是每10ms执行1800个任务.

这个对ScheduleExecutorService来说可能是个不小的性能问题.

5. 验证猜想. 我们dump 2次JFR也发现了:

B任务执行前: