虚拟机常见的监控工具

[TOC]

JDK 监控和故障处理工具总结

JDK 命令行工具

这些命令在 JDK 安装目录下的 bin 目录下:

  • jps (JVM Process Status): 类似 UNIX 的 ps 命令。用户查看所有 Java 进程的启动类、传入参数和 Java 虚拟机参数等信息;
  • jstat( JVM Statistics Monitoring Tool): 用于收集 HotSpot 虚拟机各方面的运行数据;
  • jinfo (Configuration Info for Java) : Configuration Info forJava,显示虚拟机配置信息;
  • jmap (Memory Map for Java) :生成堆转储快照;
  • jhat (JVM Heap Dump Browser ) : 用于分析 heapdump 文件,它会建立一个 HTTP/HTML 服务器,让用户可以在浏览器上查看分析结果;
  • jstack (Stack Trace for Java):生成虚拟机当前时刻的线程快照,线程快照就是当前虚拟机内每一条线程正在执行的方法堆栈的集合。

jps:查看所有 Java 进程

jps(JVM Process Status) 命令类似 UNIX 的 ps 命令。

jps:显示虚拟机执行主类名称以及这些进程的本地虚拟机唯一 ID(Local Virtual Machine Identifier,LVMID)。jps -q :只输出进程的本地虚拟机唯一 ID。

1
2
3
4
5
6
C:\Users\SnailClimb>jps
7360 NettyClient2
17396
7972 Launcher
16504 Jps
17340 NettyServerCopy to clipboardErrorCopied

jps -l:输出主类的全名,如果进程执行的是 Jar 包,输出 Jar 路径。

1
2
3
4
5
6
C:\Users\SnailClimb>jps -l
7360 firstNettyDemo.NettyClient2
17396
7972 org.jetbrains.jps.cmdline.Launcher
16492 sun.tools.jps.Jps
17340 firstNettyDemo.NettyServerCopy to clipboardErrorCopied

jps -v:输出虚拟机进程启动时 JVM 参数。

jps -m:输出传递给 Java 进程 main() 函数的参数。

jstat: 监视虚拟机各种运行状态信息

jstat(JVM Statistics Monitoring Tool) 使用于监视虚拟机各种运行状态信息的命令行工具。 它可以显示本地或者远程(需要远程主机提供 RMI 支持)虚拟机进程中的类信息、内存、垃圾收集、JIT 编译等运行数据,在没有 GUI,只提供了纯文本控制台环境的服务器上,它将是运行期间定位虚拟机性能问题的首选工具。

jstat 命令使用格式:

1
jstat -<option> [-t] [-h<lines>] <vmid> [<interval> [<count>]]Copy to clipboardErrorCopied

比如 jstat -gc -h3 31736 1000 10表示分析进程 id 为 31736 的 gc 情况,每隔 1000ms 打印一次记录,打印 10 次停止,每 3 行后打印指标头部。

常见的 option 如下:

1
2
3
- `jstat -class vmid` :显示 ClassLoader 的
`jstat -compiler vmid` :显示 JIT 编译的相关信息;相关信息;
`jstat -gc vmid` :显示与 GC 相关的堆信息;
  • jstat -class vmid :显示 ClassLoader 的相关信息;
  • jstat -compiler vmid :显示 JIT 编译的相关信息;
  • jstat -gc vmid :显示与 GC 相关的堆信息;
  • jstat -gccapacity vmid :显示各个代的容量及使用情况;
  • jstat -gcnew vmid :显示新生代信息;
  • jstat -gcnewcapcacity vmid :显示新生代大小与使用情况;
  • jstat -gcold vmid :显示老年代和永久代的行为统计,从jdk1.8开始,该选项仅表示老年代,因为永久代被移除了;
  • jstat -gcoldcapacity vmid :显示老年代的大小;
  • jstat -gcpermcapacity vmid :显示永久代大小,从jdk1.8开始,该选项不存在了,因为永久代被移除了;
  • jstat -gcutil vmid :显示垃圾收集信息;

另外,加上 -t参数可以在输出信息上加一个 Timestamp 列,显示程序的运行时间。

jinfo: 实时地查看和调整虚拟机各项参数

jinfo vmid :输出当前 jvm 进程的全部参数和系统属性 (第一部分是系统的属性,第二部分是 JVM 的参数)。

jinfo -flag name vmid :输出对应名称的参数的具体值。比如输出 MaxHeapSize、查看当前 jvm 进程是否开启打印 GC 日志 ( -XX:PrintGCDetails :详细 GC 日志模式,这两个都是默认关闭的)。

1
2
3
4
C:\Users\SnailClimb>jinfo  -flag MaxHeapSize 17340
-XX:MaxHeapSize=2124414976
C:\Users\SnailClimb>jinfo -flag PrintGC 17340
-XX:-PrintGCCopy to clipboardErrorCopied

使用 jinfo 可以在不重启虚拟机的情况下,可以动态的修改 jvm 的参数。尤其在线上的环境特别有用,请看下面的例子:

jinfo -flag [+|-]name vmid 开启或者关闭对应名称的参数。

1
2
3
4
5
6
7
C:\Users\SnailClimb>jinfo  -flag  PrintGC 17340
-XX:-PrintGC

C:\Users\SnailClimb>jinfo -flag +PrintGC 17340

C:\Users\SnailClimb>jinfo -flag PrintGC 17340
-XX:+PrintGCCopy to clipboardErrorCopied

jmap:生成堆转储快照

jmap(Memory Map for Java)命令用于生成堆转储快照。 如果不使用 jmap 命令,要想获取 Java 堆转储,可以使用 “-XX:+HeapDumpOnOutOfMemoryError” 参数,可以让虚拟机在 OOM 异常出现之后自动生成 dump 文件,Linux 命令下可以通过 kill -3 发送进程退出信号也能拿到 dump 文件。

-dump : 生成Java堆转储快照

1
2
jmap -dump:format=b,file=C:\Users\SnailClimb\Desktop\heap.dat 17340
jmap -dump:format=b,file=C:\Users\SnailClimb\Desktop\heap.hprof 17340

-heap:显示Java堆详细信息

-histo:显示堆中对象统计信息

  • jmap -heap pid

image-20210122220123744

`

jmap 的作用并不仅仅是为了获取 dump 文件,它还可以查询 finalizer 执行队列、Java 堆和永久代的详细信息,如空间使用率、当前使用的是哪种收集器等。和jinfo一样,jmap有不少功能在 Windows 平台下也是受限制的。

示例:将指定应用程序的堆快照输出到桌面。后面,可以通过 jhat、Visual VM 等工具分析该堆文件。

1
2
3
C:\Users\SnailClimb>jmap -dump:format=b,file=C:\Users\SnailClimb\Desktop\heap.hprof 17340
Dumping heap to C:\Users\SnailClimb\Desktop\heap.hprof ...
Heap dump file createdCopy to clipboardErrorCopied

jhat: 分析 heapdump 文件

jhat 用于分析 heapdump 文件,它会建立一个 HTTP/HTML 服务器,让用户可以在浏览器上查看分析结果。

1
2
3
4
5
6
7
8
9
10
C:\Users\SnailClimb>jhat C:\Users\SnailClimb\Desktop\heap.hprof
Reading from C:\Users\SnailClimb\Desktop\heap.hprof...
Dump file created Sat May 04 12:30:31 CST 2019
Snapshot read, resolving...
Resolving 131419 objects...
Chasing references, expect 26 dots..........................
Eliminating duplicate references..........................
Snapshot resolved.
Started HTTP server on port 7000
Server is ready.Copy to clipboardErrorCopied

访问 http://localhost:7000/

image-20210122221040601

jstack :生成虚拟机当前时刻的线程快照

jstack(Stack Trace for Java)命令用于生成虚拟机当前时刻的线程快照。线程快照就是当前虚拟机内每一条线程正在执行的方法堆栈的集合.

生成线程快照的目的主要是定位线程长时间出现停顿的原因,如线程间死锁、死循环、请求外部资源导致的长时间等待等都是导致线程长时间停顿的原因。线程出现停顿的时候通过jstack来查看各个线程的调用堆栈,就可以知道没有响应的线程到底在后台做些什么事情,或者在等待些什么资源。

下面是一个线程死锁的代码。我们下面会通过 jstack 命令进行死锁检查,输出死锁信息,找到发生死锁的线程。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
public class DeadLockDemo {
private static Object resource1 = new Object();//资源 1
private static Object resource2 = new Object();//资源 2

public static void main(String[] args) {
new Thread(() -> {
synchronized (resource1) {
System.out.println(Thread.currentThread() + "get resource1");
try {
Thread.sleep(1000);
} catch (InterruptedException e) {
e.printStackTrace();
}
System.out.println(Thread.currentThread() + "waiting get resource2");
synchronized (resource2) {
System.out.println(Thread.currentThread() + "get resource2");
}
}
}, "线程 1").start();

new Thread(() -> {
synchronized (resource2) {
System.out.println(Thread.currentThread() + "get resource2");
try {
Thread.sleep(1000);
} catch (InterruptedException e) {
e.printStackTrace();
}
System.out.println(Thread.currentThread() + "waiting get resource1");
synchronized (resource1) {
System.out.println(Thread.currentThread() + "get resource1");
}
}
}, "线程 2").start();
}
}Copy to clipboardErrorCopied

Output

1
2
3
4
Thread[线程 1,5,main]get resource1
Thread[线程 2,5,main]get resource2
Thread[线程 1,5,main]waiting get resource2
Thread[线程 2,5,main]waiting get resource1Copy to clipboardErrorCopied

线程 A 通过 synchronized (resource1) 获得 resource1 的监视器锁,然后通过Thread.sleep(1000);让线程 A 休眠 1s 为的是让线程 B 得到执行然后获取到 resource2 的监视器锁。线程 A 和线程 B 休眠结束了都开始企图请求获取对方的资源,然后这两个线程就会陷入互相等待的状态,这也就产生了死锁。

通过 jstack 命令分析:

1
2
3
4
5
6
7
8
9
10
11
C:\Users\SnailClimb>jps
13792 KotlinCompileDaemon
7360 NettyClient2
17396
7972 Launcher
8932 Launcher
9256 DeadLockDemo
10764 Jps
17340 NettyServer

C:\Users\SnailClimb>jstack 9256Copy to clipboardErrorCopied

输出的部分内容如下:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
Found one Java-level deadlock:
=============================
"线程 2":
waiting to lock monitor 0x000000000333e668 (object 0x00000000d5efe1c0, a java.lang.Object),
which is held by "线程 1"
"线程 1":
waiting to lock monitor 0x000000000333be88 (object 0x00000000d5efe1d0, a java.lang.Object),
which is held by "线程 2"

Java stack information for the threads listed above:
===================================================
"线程 2":
at DeadLockDemo.lambda$main$1(DeadLockDemo.java:31)
- waiting to lock <0x00000000d5efe1c0> (a java.lang.Object)
- locked <0x00000000d5efe1d0> (a java.lang.Object)
at DeadLockDemo$$Lambda$2/1078694789.run(Unknown Source)
at java.lang.Thread.run(Thread.java:748)
"线程 1":
at DeadLockDemo.lambda$main$0(DeadLockDemo.java:16)
- waiting to lock <0x00000000d5efe1d0> (a java.lang.Object)
- locked <0x00000000d5efe1c0> (a java.lang.Object)
at DeadLockDemo$$Lambda$1/1324119927.run(Unknown Source)
at java.lang.Thread.run(Thread.java:748)

Found 1 deadlock.Copy to clipboardErrorCopied

可以看到 jstack 命令已经帮我们找到发生死锁的线程的具体信息。

JDK 可视化分析工具

JConsole:Java 监视与管理控制台

JConsole 是基于 JMX 的可视化监视、管理工具。可以很方便的监视本地及远程服务器的 java 进程的内存使用情况。你可以在控制台输出console命令启动或者在 JDK 目录下的 bin 目录找到jconsole.exe然后双击启动。

连接 Jconsole

连接 Jconsole

如果需要使用 JConsole 连接远程进程,可以在远程 Java 程序启动时加上下面这些参数:

1
2
3
4
-Djava.rmi.server.hostname=外网访问 ip 地址 
-Dcom.sun.management.jmxremote.port=60001 //监控的端口号
-Dcom.sun.management.jmxremote.authenticate=false //关闭认证
-Dcom.sun.management.jmxremote.ssl=falseCopy to clipboardErrorCopied

在使用 JConsole 连接时,远程进程地址如下:

1
外网访问 ip 地址:60001 Copy to clipboardErrorCopied

查看 Java 程序概况

查看 Java 程序概况

内存监控

JConsole 可以显示当前内存的详细信息。不仅包括堆内存/非堆内存的整体信息,还可以细化到 eden 区、survivor 区等的使用情况,如下图所示。

点击右边的“执行 GC(G)”按钮可以强制应用程序执行一个 Full GC。

  • 新生代 GC(Minor GC):指发生新生代的的垃圾收集动作,Minor GC 非常频繁,回收速度一般也比较快。
  • 老年代 GC(Major GC/Full GC):指发生在老年代的 GC,出现了 Major GC 经常会伴随至少一次的 Minor GC(并非绝对),Major GC 的速度一般会比 Minor GC 的慢 10 倍以上。

内存监控

线程监控

类似我们前面讲的 jstack 命令,不过这个是可视化的。

最下面有一个”检测死锁 (D)”按钮,点击这个按钮可以自动为你找到发生死锁的线程以及它们的详细信息 。

线程监控

Visual VM:多合一故障处理工具

VisualVM 提供在 Java 虚拟机 (Java Virutal Machine, JVM) 上运行的 Java 应用程序的详细信息。在 VisualVM 的图形用户界面中,您可以方便、快捷地查看多个 Java 应用程序的相关信息。Visual VM 官网:https://visualvm.github.io/ 。Visual VM 中文文档:https://visualvm.github.io/documentation.html。

下面这段话摘自《深入理解 Java 虚拟机》。

VisualVM(All-in-One Java Troubleshooting Tool)是到目前为止随 JDK 发布的功能最强大的运行监视和故障处理程序,官方在 VisualVM 的软件说明中写上了“All-in-One”的描述字样,预示着他除了运行监视、故障处理外,还提供了很多其他方面的功能,如性能分析(Profiling)。VisualVM 的性能分析功能甚至比起 JProfiler、YourKit 等专业且收费的 Profiling 工具都不会逊色多少,而且 VisualVM 还有一个很大的优点:不需要被监视的程序基于特殊 Agent 运行,因此他对应用程序的实际性能的影响很小,使得他可以直接应用在生产环境中。这个优点是 JProfiler、YourKit 等工具无法与之媲美的。

VisualVM 基于 NetBeans 平台开发,因此他一开始就具备了插件扩展功能的特性,通过插件扩展支持,VisualVM 可以做到:

  • 显示虚拟机进程以及进程的配置、环境信息(jps、jinfo)。
  • 监视应用程序的 CPU、GC、堆、方法区以及线程的信息(jstat、jstack)。
  • dump 以及分析堆转储快照(jmap、jhat)。
  • 方法级的程序运行性能分析,找到被调用最多、运行时间最长的方法。
  • 离线程序快照:收集程序的运行时配置、线程 dump、内存 dump 等信息建立一个快照,可以将快照发送开发者处进行 Bug 反馈。
  • 其他 plugins 的无限的可能性……

CPU占满

模拟CPU占满还是比较简单,直接写一个死循环计算消耗CPU即可。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
/**
* 模拟CPU占满
*/
@GetMapping("/cpu/loop")
public void testCPULoop() throws InterruptedException {
System.out.println("请求cpu死循环");
Thread.currentThread().setName("loop-thread-cpu");
int num = 0;
while (true) {
num++;
if (num == Integer.MAX_VALUE) {
System.out.println("reset");
}
num = 0;
}

}

请求接口地址测试curl localhost:8080/cpu/loop,发现CPU立马飙升到100%

img

通过执行top -Hp 32805 查看Java线程情况

img

执行 printf '%x' 32826 获取16进制的线程id,用于dump信息查询,结果为 803a。最后我们执行jstack 32805 |grep -A 20 803a来查看下详细的dump信息。

img

这里dump信息直接定位出了问题方法以及代码行,这就定位出了CPU占满的问题。

内存泄露

模拟内存泄漏借助了ThreadLocal对象来完成,ThreadLocal是一个线程私有变量,可以绑定到线程上,在整个线程的生命周期都会存在,但是由于ThreadLocal的特殊性,ThreadLocal是基于ThreadLocalMap实现的,ThreadLocalMap的Entry继承WeakReference,而Entry的Key是WeakReference的封装,换句话说Key就是弱引用,弱引用在下次GC之后就会被回收,如果ThreadLocal在set之后不进行后续的操作,因为GC会把Key清除掉,但是Value由于线程还在存活,所以Value一直不会被回收,最后就会发生内存泄漏。

1
2
3
4
5
6
7
8
9
10
/**
* 模拟内存泄漏
*/
@GetMapping(value = "/memory/leak")
public String leak() {
System.out.println("模拟内存泄漏");
ThreadLocal<Byte[]> localVariable = new ThreadLocal<Byte[]>();
localVariable.set(new Byte[4096 * 1024]);// 为线程添加变量
return "ok";
}

我们给启动加上堆内存大小限制,同时设置内存溢出的时候输出堆栈快照并输出日志。

1
java -jar -Xms500m -Xmx500m -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/tmp/heapdump.hprof -XX:+PrintGCTimeStamps -XX:+PrintGCDetails -Xloggc:/tmp/heaplog.log analysis-demo-0.0.1-SNAPSHOT.jar

启动成功后我们循环执行100次,for i in {1..500}; do curl localhost:8080/memory/leak;done,还没执行完毕,系统已经返回500错误了。查看系统日志出现了如下异常:

1
java.lang.OutOfMemoryError: Java heap space

我们用jstat -gc pid 命令来看看程序的GC情况。

img

很明显,内存溢出了,堆内存经过45次 Full Gc 之后都没释放出可用内存,这说明当前堆内存中的对象都是存活的,有GC Roots引用,无法回收。那是什么原因导致内存溢出呢?是不是我只要加大内存就行了呢?如果是普通的内存溢出也许扩大内存就行了,但是如果是内存泄漏的话,扩大的内存不一会就会被占满,所以我们还需要确定是不是内存泄漏。我们之前保存了堆 Dump 文件,这个时候借助我们的MAT工具来分析下。导入工具选择Leak Suspects Report,工具直接就会给你列出问题报告。

img

这里已经列出了可疑的4个内存泄漏问题,我们点击其中一个查看详情。

img

这里已经指出了内存被线程占用了接近50M的内存,占用的对象就是ThreadLocal。如果想详细的通过手动去分析的话,可以点击Histogram,查看最大的对象占用是谁,然后再分析它的引用关系,即可确定是谁导致的内存溢出。

img

上图发现占用内存最大的对象是一个Byte数组,我们看看它到底被那个GC Root引用导致没有被回收。按照上图红框操作指引,结果如下图:

img

我们发现Byte数组是被线程对象引用的,图中也标明,Byte数组对像的GC Root是线程,所以它是不会被回收的,展开详细信息查看,我们发现最终的内存占用对象是被ThreadLocal对象占据了。这也和MAT工具自动帮我们分析的结果一致。

死锁

死锁会导致耗尽线程资源,占用内存,表现就是内存占用升高,CPU不一定会飙升(看场景决定),如果是直接new线程,会导致JVM内存被耗尽,报无法创建线程的错误,这也是体现了使用线程池的好处。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
 ExecutorService service = new ThreadPoolExecutor(4, 10,
0, TimeUnit.SECONDS, new LinkedBlockingQueue<Runnable>(1024),
Executors.defaultThreadFactory(),
new ThreadPoolExecutor.AbortPolicy());
/**
* 模拟死锁
*/
@GetMapping("/cpu/test")
public String testCPU() throws InterruptedException {
System.out.println("请求cpu");
Object lock1 = new Object();
Object lock2 = new Object();
service.submit(new DeadLockThread(lock1, lock2), "deadLookThread-" + new Random().nextInt());
service.submit(new DeadLockThread(lock2, lock1), "deadLookThread-" + new Random().nextInt());
return "ok";
}

public class DeadLockThread implements Runnable {
private Object lock1;
private Object lock2;

public DeadLockThread1(Object lock1, Object lock2) {
this.lock1 = lock1;
this.lock2 = lock2;
}

@Override
public void run() {
synchronized (lock2) {
System.out.println(Thread.currentThread().getName()+"get lock2 and wait lock1");
try {
TimeUnit.MILLISECONDS.sleep(2000);
} catch (InterruptedException e) {
e.printStackTrace();
}
synchronized (lock1) {
System.out.println(Thread.currentThread().getName()+"get lock1 and lock2 ");
}
}
}
}

我们循环请求接口2000次,发现不一会系统就出现了日志错误,线程池和队列都满了,由于我选择的当队列满了就拒绝的策略,所以系统直接抛出异常。

1
java.util.concurrent.RejectedExecutionException: Task java.util.concurrent.FutureTask@2760298 rejected from java.util.concurrent.ThreadPoolExecutor@7ea7cd51[Running, pool size = 10, active threads = 10, queued tasks = 1024, completed tasks = 846]

通过ps -ef|grep java命令找出 Java 进程 pid,执行jstack pid 即可出现java线程堆栈信息,这里发现了5个死锁,我们只列出其中一个,很明显线程pool-1-thread-2锁住了0x00000000f8387d88等待0x00000000f8387d98锁,线程pool-1-thread-1锁住了0x00000000f8387d98等待锁0x00000000f8387d88,这就产生了死锁。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
Java stack information for the threads listed above:
===================================================
"pool-1-thread-2":
at top.luozhou.analysisdemo.controller.DeadLockThread2.run(DeadLockThread.java:30)
- waiting to lock <0x00000000f8387d98> (a java.lang.Object)
- locked <0x00000000f8387d88> (a java.lang.Object)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)
"pool-1-thread-1":
at top.luozhou.analysisdemo.controller.DeadLockThread1.run(DeadLockThread.java:30)
- waiting to lock <0x00000000f8387d88> (a java.lang.Object)
- locked <0x00000000f8387d98> (a java.lang.Object)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)

Found 5 deadlocks.

线程频繁切换

上下文切换会导致将大量CPU时间浪费在寄存器、内核栈以及虚拟内存的保存和恢复上,导致系统整体性能下降。当你发现系统的性能出现明显的下降时候,需要考虑是否发生了大量的线程上下文切换。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
 @GetMapping(value = "/thread/swap")
public String theadSwap(int num) {
System.out.println("模拟线程切换");
for (int i = 0; i < num; i++) {
new Thread(new ThreadSwap1(new AtomicInteger(0)),"thread-swap"+i).start();
}
return "ok";
}
public class ThreadSwap1 implements Runnable {
private AtomicInteger integer;

public ThreadSwap1(AtomicInteger integer) {
this.integer = integer;
}

@Override
public void run() {
while (true) {
integer.addAndGet(1);
Thread.yield(); //让出CPU资源
}
}
}

这里我创建多个线程去执行基础的原子+1操作,然后让出 CPU 资源,理论上 CPU 就会去调度别的线程,我们请求接口创建100个线程看看效果如何,curl localhost:8080/thread/swap?num=100。接口请求成功后,我们执行`vmstat 1 10,表示每1秒打印一次,打印10次,线程切换采集结果如下:

1
2
3
4
5
6
7
8
procs -----------memory---------- ---swap-- -----io---- -system-- ------cpu-----
r b swpd free buff cache si so bi bo in cs us sy id wa st
101 0 128000 878384 908 468684 0 0 0 0 4071 8110498 14 86 0 0 0
100 0 128000 878384 908 468684 0 0 0 0 4065 8312463 15 85 0 0 0
100 0 128000 878384 908 468684 0 0 0 0 4107 8207718 14 87 0 0 0
100 0 128000 878384 908 468684 0 0 0 0 4083 8410174 14 86 0 0 0
100 0 128000 878384 908 468684 0 0 0 0 4083 8264377 14 86 0 0 0
100 0 128000 878384 908 468688 0 0 0 108 4182 8346826 14 86 0 0 0

这里我们关注4个指标,r,cs,us,sy

r=100,说明等待的进程数量是100,线程有阻塞。

cs=800多万,说明每秒上下文切换了800多万次,这个数字相当大了。

us=14,说明用户态占用了14%的CPU时间片去处理逻辑。

sy=86,说明内核态占用了86%的CPU,这里明显就是做上下文切换工作了。

我们通过top命令以及top -Hp pid查看进程和线程CPU情况,发现Java线程CPU占满了,但是线程CPU使用情况很平均,没有某一个线程把CPU吃满的情况。

1
2
3
4
5
6
7
8
PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND                                                                            
87093 root 20 0 4194788 299056 13252 S 399.7 16.1 65:34.67 java
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
87189 root 20 0 4194788 299056 13252 R 4.7 16.1 0:41.11 java
87129 root 20 0 4194788 299056 13252 R 4.3 16.1 0:41.14 java
87130 root 20 0 4194788 299056 13252 R 4.3 16.1 0:40.51 java
87133 root 20 0 4194788 299056 13252 R 4.3 16.1 0:40.59 java
87134 root 20 0 4194788 299056 13252 R 4.3 16.1 0:40.95 java

结合上面用户态CPU只使用了14%,内核态CPU占用了86%,可以基本判断是Java程序线程上下文切换导致性能问题。

我们使用pidstat命令来看看Java进程内部的线程切换数据,执行pidstat -p 87093 -w 1 10,采集数据如下:

1
2
3
4
5
6
7
8
9
10
11
11:04:30 PM   UID       TGID       TID   cswch/s nvcswch/s  Command
11:04:30 PM 0 - 87128 0.00 16.07 |__java
11:04:30 PM 0 - 87129 0.00 15.60 |__java
11:04:30 PM 0 - 87130 0.00 15.54 |__java
11:04:30 PM 0 - 87131 0.00 15.60 |__java
11:04:30 PM 0 - 87132 0.00 15.43 |__java
11:04:30 PM 0 - 87133 0.00 16.02 |__java
11:04:30 PM 0 - 87134 0.00 15.66 |__java
11:04:30 PM 0 - 87135 0.00 15.23 |__java
11:04:30 PM 0 - 87136 0.00 15.33 |__java
11:04:30 PM 0 - 87137 0.00 16.04 |__java

根据上面采集的信息,我们知道Java的线程每秒切换15次左右,正常情况下,应该是个位数或者小数。结合这些信息我们可以断定Java线程开启过多,导致频繁上下文切换,从而影响了整体性能。

为什么系统的上下文切换是每秒800多万,而 Java 进程中的某一个线程切换才15次左右?

系统上下文切换分为三种情况:

1、多任务:在多任务环境中,一个进程被切换出CPU,运行另外一个进程,这里会发生上下文切换。

2、中断处理:发生中断时,硬件会切换上下文。在vmstat命令中是in

3、用户和内核模式切换:当操作系统中需要在用户模式和内核模式之间进行转换时,需要进行上下文切换,比如进行系统函数调用。

Linux 为每个 CPU 维护了一个就绪队列,将活跃进程按照优先级和等待 CPU 的时间排序,然后选择最需要 CPU 的进程,也就是优先级最高和等待 CPU 时间最长的进程来运行。也就是vmstat命令中的r

那么,进程在什么时候才会被调度到 CPU 上运行呢?

  • 进程执行完终止了,它之前使用的 CPU 会释放出来,这时再从就绪队列中拿一个新的进程来运行
  • 为了保证所有进程可以得到公平调度,CPU 时间被划分为一段段的时间片,这些时间片被轮流分配给各个进程。当某个进程时间片耗尽了就会被系统挂起,切换到其它等待 CPU 的进程运行。
  • 进程在系统资源不足时,要等待资源满足后才可以运行,这时进程也会被挂起,并由系统调度其它进程运行。
  • 当进程通过睡眠函数 sleep 主动挂起时,也会重新调度。
  • 当有优先级更高的进程运行时,为了保证高优先级进程的运行,当前进程会被挂起,由高优先级进程来运行。
  • 发生硬件中断时,CPU 上的进程会被中断挂起,转而执行内核中的中断服务程序。

结合我们之前的内容分析,阻塞的就绪队列是100左右,而我们的CPU只有4核,这部分原因造成的上下文切换就可能会相当高,再加上中断次数是4000左右和系统的函数调用等,整个系统的上下文切换到800万也不足为奇了。Java内部的线程切换才15次,是因为线程使用Thread.yield()来让出CPU资源,但是CPU有可能继续调度该线程,这个时候线程之间并没有切换,这也是为什么内部的某个线程切换次数并不是非常大的原因。

总结

本文模拟了常见的性能问题场景,分析了如何定位CPU100%、内存泄漏、死锁、线程频繁切换问题。分析问题我们需要做好两件事,第一,掌握基本的原理,第二,借助好工具。本文也列举了分析问题的常用工具和命令,希望对你解决问题有所帮助。当然真正的线上环境可能十分复杂,并没有模拟的环境那么简单,但是原理是一样的,问题的表现也是类似的,我们重点抓住原理,活学活用,相信复杂的线上问题也可以顺利解决。