前言
由于日常开发过程中一些线程池的不规范使用及不能正常评估CPU计算密集型资源耗费或不正确的处理方式或过度的 I/O 操作可能会导致线程忙碌地等待 I/O 完成,从而影响 CPU 使用率,以及错误的线程使用便会出现CPU标高的问题
问题排查与定位
top命令查看占用CPU资源最高的进程
top
执行结果
top - 10:05:08 up 297 days, 19:11, 0 users, load average: 15.55, 18.55, 17.94
Tasks: 29 total, 1 running, 28 sleeping, 0 stopped, 0 zombie
%Cpu(s): 11.6 us, 2.8 sy, 0.0 ni, 84.9 id, 0.0 wa, 0.0 hi, 0.7 si, 0.0 st
KiB Mem : 15128348+total, 98081894+free, 36106867+used, 17094715+buff/cache
KiB Swap: 0 total, 0 free, 0 used. 11453130+avail MemPID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
29 tomcat 20 0 18.6g 3.0g 15152 S 131.6 0.2 3439:15 java
1 tomcat 20 0 16124 2732 1376 S 0.0 0.0 0:00.16 init.sh
29056 tomcat 20 0 16012 2608 1280 S 0.0 0.0 0:00.05 sh
29062 tomcat 20 0 16012 1756 420 S 0.0 0.0 0:00.01 sh
29064 tomcat 20 0 13972 940 660 S 0.0 0.0 0:00.01 script
29072 tomcat 20 0 13976 696 412 S 0.0 0.0 0:00.01 script
29074 tomcat 20 0 16264 3152 1632 S 0.0 0.0 0:00.26 bash
47800 tomcat 20 0 16012 2608 1280 S 0.0 0.0 0:00.05 sh
47806 tomcat 20 0 16012 1752 416 S 0.0 0.0 0:00.01 sh
由执行top结果可以查看得出 PID:29进程占用CPU资源最高,对29进程继续详细分析
查看最高负载进程下的高负载线程
top -Hp PID
执行结果
top - 10:09:20 up 297 days, 19:15, 0 users, load average: 13.05, 15.62, 16.90
Threads: 232 total, 0 running, 232 sleeping, 0 stopped, 0 zombie
%Cpu(s): 11.4 us, 3.0 sy, 0.0 ni, 84.8 id, 0.0 wa, 0.0 hi, 0.7 si, 0.0 st
KiB Mem : 15128348+total, 98010732+free, 36103891+used, 17168852+buff/cache
KiB Swap: 0 total, 0 free, 0 used. 11453364+avail MemPID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
2722 tomcat 20 0 18.6g 3.0g 14188 S 25.9 0.2 17:33.14 java
113 tomcat 20 0 18.6g 3.0g 14188 S 25.6 0.2 794:08.01 java
114 tomcat 20 0 18.6g 3.0g 14188 S 19.3 0.2 896:15.95 java
115 tomcat 20 0 18.6g 3.0g 14188 S 11.0 0.2 236:24.02 java
117 tomcat 20 0 18.6g 3.0g 14188 S 7.0 0.2 129:25.74 java
116 tomcat 20 0 18.6g 3.0g 14188 S 6.6 0.2 138:27.95 java
2679 tomcat 20 0 18.6g 3.0g 14188 S 5.6 0.2 2:53.99 java
2642 tomcat 20 0 18.6g 3.0g 14188 S 5.0 0.2 3:06.70 java
2657 tomcat 20 0 18.6g 3.0g 14188 S 4.7 0.2 3:02.93 java
2659 tomcat 20 0 18.6g 3.0g 14188 S 4.3 0.2 3:05.57 java
2694 tomcat 20 0 18.6g 3.0g 14188 S 4.3 0.2 2:46.57 java
2513 tomcat 20 0 18.6g 3.0g 14188 S 4.0 0.2 3:13.60 java
54 tomcat 20 0 18.6g 3.0g 14188 S 3.3 0.2 63:47.13 java
2513 tomcat 20 0 18.6g 3.0g 14188 S 2.7 0.2 3:13.48 java
255002 tomcat 20 0 18.6g 3.0g 14188 S 2.0 0.2 0:23.05 java
2687 tomcat 20 0 18.6g 3.0g 14188 S 1.7 0.2 2:50.75 java
130 tomcat 20 0 18.6g 3.0g 14188 S 1.3 0.2 71:20.39 java
2642 tomcat 20 0 18.6g 3.0g 14188 S 1.3 0.2 3:06.55 java
103 tomcat 20 0 18.6g 3.0g 14188 S 1.0 0.2 3:21.51 java
2689 tomcat 20 0 18.6g 3.0g 14188 S 1.0 0.2 0:25.99 java
2694 tomcat 20 0 18.6g 3.0g 14188 S 1.0 0.2 2:46.44 java
31 tomcat 20 0 18.6g 3.0g 14188 S 0.7 0.2 33:39.14 java
93 tomcat 20 0 18.6g 3.0g 14188 S 0.7 0.2 2:32.87 java
109 tomcat 20 0 18.6g 3.0g 14188 S 0.7 0.2 6:27.98 java
2673 tomcat 20 0 18.6g 3.0g 14188 S 0.7 0.2 0:29.97 java
2677 tomcat 20 0 18.6g 3.0g 14188 R 0.7 0.2 0:28.96 java
2706 tomcat 20 0 18.6g 3.0g 14188 S 0.7 0.2 0:21.81 java
24683 tomcat 20 0 18.6g 3.0g 14188 S 0.7 0.2 0:16.25 java
32 tomcat 20 0 18.6g 3.0g 14188 S 0.3 0.2 33:39.53 java
34 tomcat 20 0 18.6g 3.0g 14188 S 0.3 0.2 15:28.61 java
80 tomcat 20 0 18.6g 3.0g 14188 S 0.3 0.2 3:41.48 java
81 tomcat 20 0 18.6g 3.0g 14188 S 0.3 0.2 4:15.09 java
85 tomcat 20 0 18.6g 3.0g 14188 S 0.3 0.2 4:40.66 java
86 tomcat 20 0 18.6g 3.0g 14188 S 0.3 0.2 0:57.09 java
87 tomcat 20 0 18.6g 3.0g 14188 S 0.3 0.2 4:37.74 java
列表说明
- PID:线程的进程 ID。
- USER:线程的所有者。
- PR:线程的优先级。
- NI:线程的优先级调整值(nice 值)。
- VIRT:线程使用的虚拟内存总量。
- RES:线程使用的常驻内存总量(实际物理内存)。
- SHR:线程共享的内存总量。
- S:线程的状态(例如 R 表示运行,S 表示休眠)。
- %CPU:线程使用的 CPU 百分比。
- %MEM:线程使用的物理内存百分比。
- TIME+:线程使用的 CPU 时间总量。
- COMMAND:线程的命令或线程名称。
基于线程状态列可以看出大部分线程处于休眠状态,由于我们使用jstack,则需要将对应的线程PID转换为十六进制,在日常使用gdb
、jstack
、pstack都需要将PID转为十六进制
PID转为十六进制
printf '%x\n' <pid>
获取线程堆栈信息
# 获取进程的堆栈信息
jstack <pid>
# 获取指定线程的堆栈信息
jstack <pid> | grep 十六进制线程名称
执行后便可查看对应的堆栈结果
java.lang.Thread.State: TIMED_WAITING (parking) at sun.misc.Unsafe.park(Native Method) - parking to wait for <0x000000075909fc38> (a java.util.concurrent.CompletableFuture$Signaller) at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215) at java.util.concurrent.CompletableFuture$Signaller.block(CompletableFuture.java:1709) at java.util.concurrent.ForkJoinPool.managedBlock(ForkJoinPool.java:3313) at java.util.concurrent.CompletableFuture.timedGet(CompletableFuture.java:1788) at java.util.concurrent.CompletableFuture.get(CompletableFuture.java:1928) at io.lettuce.core.protocol.AsyncCommand.await(AsyncCommand.java:83) at io.lettuce.core.LettuceFutures.awaitOrCancel(LettuceFutures.java:112) at io.lettuce.core.cluster.ClusterFutureSyncInvocationHandler.handleInvocation(ClusterFutureSyncInvocationHandler.java:123) at io.lettuce.core.internal.AbstractInvocationHandler.invoke(AbstractInvocationHandler.java:80) at com.sun.proxy.$Proxy255.hset(Unknown Source) at org.springframework.data.redis.connection.lettuce.LettuceHashCommands.hSet(LettuceHashCommands.java:69) at org.springframework.data.redis.connection.DefaultedRedisConnection.hSet(DefaultedRedisConnection.java:898) at org.springframework.data.redis.core.DefaultHashOperations.lambda$put$9(DefaultHashOperations.java:192) at org.springframework.data.redis.core.DefaultHashOperations$$Lambda$1083/926110242.doInRedis(Unknown Source) at org.springframework.data.redis.core.RedisTemplate.execute(RedisTemplate.java:225) at org.springframework.data.redis.core.RedisTemplate.execute(RedisTemplate.java:185) at org.springframework.data.redis.core.AbstractOperations.execute(AbstractOperations.java:96) -- - locked <0x000000078aa3c790> (a sun.nio.ch.EPollSelectorImpl) at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:97) at org.apache.tomcat.util.net.NioBlockingSelector$BlockPoller.run(NioBlockingSelector.java:313)
线程堆栈分析
线程状态:TIMED_WAITING (parking): 这个状态通常表示线程正在等待某个条件或超时。
Unsafe.park
是一种低级别的阻塞调用,用于在等待特定条件时暂停线程的执行。堆栈调用链:
java.util.concurrent.CompletableFuture$Signaller.block
:线程在等待CompletableFuture
的结果。java.util.concurrent.ForkJoinPool.managedBlock
:CompletableFuture
正在等待一个可以被ForkJoinPool
管理的任务完成。io.lettuce.core.protocol.AsyncCommand.await
:这是 Lettuce 库的代码,说明线程在等待 Redis 操作的结果。io.lettuce.core.LettuceFutures.awaitOrCancel
:用于处理异步 Redis 命令的结果。org.springframework.data.redis.connection.lettuce.LettuceHashCommands.hSet
:Spring Data Redis 的代码,执行 Redis 哈希操作的hSet
方法。org.springframework.data.redis.core.DefaultHashOperations.lambda$put$9
:Spring Data Redis 的put
操作。锁定信息:
sun.nio.ch.EPollSelectorImpl
:线程在等待 I/O 操作,可能表示网络通信或者事件的轮询。
再基于实际的代码层分析便可具体定位具体原因,此处实际造成原因是由于使用FrokjoinPool造成
ForkJoinPool.commonPool().submit(() -> dataList.parallelStream().forEach(data-> {
try {
System.out.println("具体计算逻辑,及计算逻辑耗时较高,1秒左右");
} catch (Exception e) {
}
})).join();
总结
使用了
ForkJoinPool.commonPool()
来提交一个任务,该任务内部使用parallelStream()
来并行处理dataList
中的每个data
。如果dataList
有多个元素,parallelStream()
将会启动多个线程并发处理每个data
,这可能导致高 CPU 使用率。关键问题
CPU 使用率 200%:
- 机器为2核,因此 CPU 使用率的总和为 200% 表示两个核心都被充分利用了。由于
ForkJoinPool.commonPool()
默认使用与可用核心数相同的线程数,并行处理的任务可能会导致 CPU 负荷过重。单次
calc
方法执行时间:
- 如果每个
calc
方法调用需要约 1 秒钟,并且dataList
包含大量数据,所有的线程同时在执行这些计算任务将会显著增加 CPU 使用率