以一个例子来演示排查服务器cpu占用率过高的问题。
准备
将下面的代码文件上传到服务器上,然后使用javac编译,并使用java命令将程序跑起来。
public class JStackCase {
public static void main(String[] args) { ExecutorService executor = Executors.newFixedThreadPool(5); executor.submit(new Task()); executor.submit(new Task()); } } class Task implements Runnable { @Override public void run() { synchronized (this) { calculate(); } } public void calculate() { int i = 0; while (true) { i++; } } }
显然,这段程序会导致CPU占用率较高。接下来,我们进行问题排查。
1.定位进程
使用top命令查看cpu占用情况,默认按cpu使用率从高到低排序。我们发现pid为6624的进程占用了70%的cpu。
[root@localhost bin]# top PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 6624 root 20 0 2249296 18380 10704 S 70.0 1.8 6:00.17 java 6723 root 20 0 157716 2112 1472 R 5.0 0.2 0:00.03 top 1 root 20 0 193724 3608 1972 S 0.0 0.4 0:07.07 systemd 2 root 20 0 0 0 0 S 0.0 0.0 0:00.01 kthreadd 3 root 20 0 0 0 0 S 0.0 0.0 0:13.54 ksoftirqd/0 5 root 0 -20 0 0 0 S 0.0 0.0 0:00.00 kworker/0:0H 7 root rt 0 0 0 0 S 0.0 0.0 0:00.40 migration/0 8 root 20 0 0 0 0 S 0.0 0.0 0:00.00 rcu_bh 9 root 20 0 0 0 0 S 0.0 0.0 0:04.98 rcu_sched 10 root rt 0 0 0 0 S 0.0 0.0 0:04.42 watchdog/0 12 root 20 0 0 0 0 S 0.0 0.0 0:00.00 kdevtmpfs 13 root 0 -20 0 0 0 S 0.0 0.0 0:00.00 netns 14 root 20 0 0 0 0 S 0.0 0.0 0:00.00 khungtaskd 15 root 0 -20 0 0 0 S 0.0 0.0 0:00.00 writeback 16 root 0 -20 0 0 0 S 0.0 0.0 0:00.00 kintegrityd 17 root 0 -20 0 0 0 S 0.0 0.0 0:00.00 bioset 18 root 0 -20 0 0 0 S 0.0 0.0 0:00.00 kblockd 19 root 0 -20 0 0 0 S 0.0 0.0 0:00.00 md 25 root 20 0 0 0 0 S 0.0 0.0 0:10.50 kswapd0 26 root 25 5 0 0 0 S 0.0 0.0 0:00.00 ksmd 27 root 39 19 0 0 0 S 0.0 0.0 0:00.21 khugepaged 28 root 0 -20 0 0 0 S 0.0 0.0 0:00.00 crypto 36 root 0 -20 0 0 0 S 0.0 0.0 0:00.00 kthrotld 38 root 0 -20 0 0 0 S 0.0 0.0 0:00.00 kmpath_rdacd 39 root 0 -20 0 0 0 S 0.0 0.0 0:00.00 kpsmoused
2.定位线程
查看pid为6624的进程下的线程cpu占用情况。发现6634和6635线程几乎占用了大部分的cpu。
[root@localhost bin]# top -Hp 6624
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 6634 root 20 0 2249296 16532 8852 R 49.8 1.7 6:34.75 java 6635 root 20 0 2249296 16532 8852 R 49.5 1.7 6:34.69 java 6624 root 20 0 2249296 16532 8852 S 0.0 1.7 0:00.04 java 6625 root 20 0 2249296 16532 8852 S 0.0 1.7 0:00.09 java 6626 root 20 0 2249296 16532 8852 S 0.0 1.7 0:00.01 java 6627 root 20 0 2249296 16532 8852 S 0.0 1.7 0:00.00 java 6628 root 20 0 2249296 16532 8852 S 0.0 1.7 0:00.00 java 6629 root 20 0 2249296 16532 8852 S 0.0 1.7 0:00.00 java 6630 root 20 0 2249296 16532 8852 S 0.0 1.7 0:00.00 java 6631 root 20 0 2249296 16532 8852 S 0.0 1.7 0:00.00 java 6632 root 20 0 2249296 16532 8852 S 0.0 1.7 0:00.00 java 6633 root 20 0 2249296 16532 8852 S 0.0 1.7 0:00.54 java
3.定位代码
接下来jstack就要上场了。可以使用jstack -l [pid]查看线程的堆栈信息。
jstack -l [pid] //进程id
当然,我们可以过滤我们只关注的线程的转储信息。
将线程pid转为16进制
因为thread id在栈信息中是以十六进制的形式显示的,所以可以使用printf "%x \n" [pid]命令将线程pid转为16进制。
[root@localhost bin]# printf "%x \n" 6634 19ea [root@localhost bin]# printf "%x \n" 6635 19eb
过滤19ea线程的堆栈信息,使用jstack -l <pid> | grep <thread-hex-id> -A 10。-A 10
参数用来指定显示行数,否则只会显示一行信息。
[root@localhost bin]# jstack -l 6624 | grep 19ea -A 10
"pool-1-thread-1" #8 prio=5 os_prio=0 tid=0x00007f22e00e4800 nid=0x19ea runnable [0x00007f22d0729000]
java.lang.Thread.State: RUNNABLE
at Task.calculate(JStackCase.java:26) at Task.run(JStackCase.java:19) - locked <0x00000000f0a60ff8> (a Task) 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:1142) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) at java.lang.Thread.run(Thread.java:748)
于是,定位到代码JstackCase类中第26行,通过信息可知是线程池引起的cpu占用率过高的问题,接下来分析对应的代码即可。
通常,在线上环境远比这复杂,所以需要多次获取线程堆栈信息,进行对比综合分析。所以,仅仅单独分析一个文件是可能并没有太大意义的。
当然我们也可以使用其它的工具来排查问题,比如系统自带的perf,Alibaba开源的工具Arthas等。