jstack排查CPU标高

前言

由于日常开发过程中一些线程池的不规范使用及不能正常评估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 Mem 

    PID 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 Mem 

   PID 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转换为十六进制,在日常使用gdbjstackpstack都需要将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)

线程堆栈分析

  1. 线程状态:TIMED_WAITING (parking): 这个状态通常表示线程正在等待某个条件或超时。Unsafe.park 是一种低级别的阻塞调用,用于在等待特定条件时暂停线程的执行。

  2. 堆栈调用链

    • java.util.concurrent.CompletableFuture$Signaller.block:线程在等待 CompletableFuture 的结果。
    • java.util.concurrent.ForkJoinPool.managedBlockCompletableFuture 正在等待一个可以被 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 操作。
  3. 锁定信息

    • 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 使用率。

关键问题

  1. CPU 使用率 200%

    • 机器为2核,因此 CPU 使用率的总和为 200% 表示两个核心都被充分利用了。由于 ForkJoinPool.commonPool() 默认使用与可用核心数相同的线程数,并行处理的任务可能会导致 CPU 负荷过重。
  2. 单次 calc 方法执行时间

    • 如果每个 calc 方法调用需要约 1 秒钟,并且 dataList包含大量数据,所有的线程同时在执行这些计算任务将会显著增加 CPU 使用率
  • 14
    点赞
  • 10
    收藏
    觉得还不错? 一键收藏
  • 0
    评论
评论
添加红包

请填写红包祝福语或标题

红包个数最小为10个

红包金额最低5元

当前余额3.43前往充值 >
需支付:10.00
成就一亿技术人!
领取后你会自动成为博主和红包主的粉丝 规则
hope_wisdom
发出的红包
实付
使用余额支付
点击重新获取
扫码支付
钱包余额 0

抵扣说明:

1.余额是钱包充值的虚拟货币,按照1:1的比例进行支付金额的抵扣。
2.余额无法直接购买下载,可以购买VIP、付费专栏及课程。

余额充值