排查Java进程CPU占用高之三板斧 |
您所在的位置：网站首页 › 宽带发生故障怎么排查问题呢 › 排查Java进程CPU占用高之三板斧 |
排查Java进程CPU占用高之三板斧
|
写在前面
线上环境突然出现Java进程CPU占用率持续超过100%的问题，该如何排查并定位呢？ 问题一：我们如何知道线上环境的那个服务器（或者哪个Docker容器）出现了CPU持续高的故障了呢？ 如果是有比较完善的监控设施，当出现CPU持续高时可以通过发送报警通知的方式告知开发人员，如果没有监控通知，那只能通过用户侧感知了，比如操作响应慢，甚至出现了服务不可用的现象。 问题二：存在哪些可能的原因会导致Java进程的CPU占用率会持续高呢？ 如果是突然出现的问题，可能是跟当时并发压力有关，比如用户访问量突然增多触发大量的TCP连接请求，也可能是触发了某个代码逻辑的BUG进入死循环等。根据经验，会引起Java进程CPU占用率持续高的原因可能有如下几个： 并发量突然增大引起TCP连接数陡增，Tomcat容器处理不过来 数据量猛然变大引起频繁Full GC，这个可以从GC日志可以看出来 如果打印日志非常多，也可能导致CPU持续高，当然这个原因一般不会突然才冒出来，在测试阶段就能感知了既然存在多种可能的原因，那么在排查的时候就需要依次定位了。 线程堆栈不论是何种原因引起的Java进程CPU占用率高问题，排查的入口都是先从线程堆栈信息入手。 可以查看Java线程堆栈信息的工具有：jstack命令，Arthas工具。 jstack命令jstack命令是JDK自带的，在使用它查看进程堆栈之前先要找到具体的进程ID。 先通过top命令确定CPU占用高的Java进程ID，如下示例： ubuntu@epic-doberman:~$ top top - 15:49:15 up 30 min, 2 users, load average: 0.86, 0.32, 0.12 Tasks: 122 total, 1 running, 121 sleeping, 0 stopped, 0 zombie %Cpu(s): 25.3 us, 0.0 sy, 0.0 ni, 74.6 id, 0.0 wa, 0.0 hi, 0.2 si, 0.0 st MiB Mem : 7925.5 total, 6999.9 free, 454.5 used, 711.5 buff/cache MiB Swap: 0.0 total, 0.0 free, 0.0 used. 7470.9 avail Mem PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 8632 ubuntu 20 0 4386476 28076 18604 S 99.7 0.3 1:56.00 java 1 root 20 0 22708 13540 9444 S 0.0 0.2 0:02.23 systemd 2 root 20 0 0 0 0 S 0.0 0.0 0:00.00 kthreadd 3 root 20 0 0 0 0 S 0.0 0.0 0:00.00 pool_workqueue_release 4 root 0 -20 0 0 0 I 0.0 0.0 0:00.00 kworker/R-rcu_g 5 root 0 -20 0 0 0 I 0.0 0.0 0:00.00 kworker/R-rcu_p 6 root 0 -20 0 0 0 I 0.0 0.0 0:00.00 kworker/R-slub_ 7 root 0 -20 0 0 0 I 0.0 0.0 0:00.00 kworker/R-netns 9 root 20 0 0 0 0 I 0.0 0.0 0:00.31 kworker/0:1-events 10 root 0 -20 0 0 0 I 0.0 0.0 0:00.00 kworker/0:0H-events_highpri 12 root 0 -20 0 0 0 I 0.0 0.0 0:00.00 kworker/R-mm_pe 13 root 20 0 0 0 0 I 0.0 0.0 0:00.00 rcu_tasks_kthread如上，CPU占用高的进程ID为8632。.. 接着，使用JDK自带的jstack命令导出进程堆栈文件。 $ jstack Usage: jstack [-l] (to connect to running process) jstack -F [-m] [-l] (to connect to a hung process) jstack [-m] [-l] (to connect to a core file) jstack [-m] [-l] [server_id@] (to connect to a remote debug server) Options: -F to force a thread dump. Use when jstack does not respond (process is hung) -m to print both java and native frames (mixed mode) -l long listing. Prints additional information about locks -h or -help to print this help message $ jstack 8632 > 8632.tdump将进程8632的线程堆栈信息导出到文件8632.tdump之后，使用JDK自带的jvisualvm工具分析堆栈信息。
在线程堆栈文件中查找并分析状态为RUNNABLE的线程，结合代码进行分析，如果能直接确定出问题原因则修复代码即可。
对于使用jstack命令查看线程堆栈，可以结合shell脚本来实现快速查看，如下示例： #!/bin/bash # Desc: 查看Java进程CPU使用率高的线程堆栈信息 # Name: show_java_process_thread_stack.sh echo "Show java process thread stack" pid=$1 if [ ! "$pid" ]; then echo "Usage: sh $0 pid" echo " e.g: sh $0 1234" echo "" exit 1 fi top -H -p "$pid"|head -20 echo "" top_thread_id=`top -H -p $pid|head -8|awk '/java/{print $2}'` #echo "top cpu thread: $top_thread_id" thread_id_hex=`printf "%x" "$top_thread_id"` #echo "$thread_id_hex" jstack "$pid"|grep "$thread_id_hex" -A 100 > jstack_tmp cat jstack_tmp rm -rf jstack_tmp #echo "Done."如果是代码死循环问题，通常在分析线程堆栈之后很快就能定位到具体的位置。
而倘若是因为大量用户请求引起的TCP连接数很多，此时在线程堆栈中也会有所体现，如下示例：
同时，再结合相关网络连接查看命令，也能大致确认（此时会存在大量TCP连接处于TIME_WAIT状态），参考查看linux中的TCP连接数。 $ sudo netstat -anpt
使用Arthas排查查看线程堆栈信息非常方便，通过如下步骤使用arthas可以便捷地查看到线程堆栈信息，对于定位可能存在死循环的代码位置非常有帮助。 第一步：启动arthas # 使用与目标进程相同的用户权限启动arthas $ java -jar arthas-boot.jar ubuntu@epic-doberman:~/Scripts$ java -jar arthas-boot.jar [INFO] JAVA_HOME: /usr/lib/jvm/java-8-openjdk-amd64/jre [INFO] arthas-boot version: 3.7.2 [INFO] Found existing java process, please choose one and input the serial number of the process, eg : 1. Then hit ENTER. * [1]: 2730 test-java-util.jar第二步：选择目标进程编号并回车 1 [INFO] arthas home: /home/ubuntu/.arthas/lib/3.7.2/arthas [INFO] Try to attach process 2730 Picked up JAVA_TOOL_OPTIONS: [INFO] Attach process 2730 success. [INFO] arthas-client connect 127.0.0.1 3658 ,---. ,------. ,--------.,--. ,--. ,---. ,---. / O \ | .--. ''--. .--'| '--' | / O \ ' .-' | .-. || '--'.' | | | .--. || .-. |`. `-. | | | || |\ \ | | | | | || | | |.-' | `--' `--'`--' '--' `--' `--' `--'`--' `--'`-----' wiki https://arthas.aliyun.com/doc tutorials https://arthas.aliyun.com/doc/arthas-tutorials.html version 3.7.2 main_class pid 2730 time 2024-06-13 16:24:38 [arthas@2730]$第三步：执行dashboard命令找到CPU占用率高的线程ID $ dashboard
第四步：执行thread 查看指定线程的堆栈信息 [arthas@2730]$ thread 1 "main" Id=1 RUNNABLE at org.chench.extra.java.mock.DeadLoopSampleMock.mock(DeadLoopSampleMock.java:20) at org.chench.extra.java.mock.DeadLoopSampleMock.main(DeadLoopSampleMock.java:14)如果存在多个线程占用CPU都比较高的情况，可以直接执行thread -n 查看当前最忙的前N个线程并打印堆栈。 # 查看当前最繁忙的前3个线程堆栈，各线程堆栈信息之间通过2个空行分隔 $ thread -n 3 "main" Id=1 cpuUsage=99.96% deltaTime=204ms time=1835502ms RUNNABLE at org.chench.extra.java.mock.DeadLoopSampleMock.mock(DeadLoopSampleMock.java:20) at org.chench.extra.java.mock.DeadLoopSampleMock.main(DeadLoopSampleMock.java:14) "C2 CompilerThread0" [Internal] cpuUsage=1.55% deltaTime=3ms time=823ms "arthas-command-execute" Id=57 cpuUsage=0.12% deltaTime=0ms time=6ms RUNNABLE at sun.management.ThreadImpl.dumpThreads0(Native Method) at sun.management.ThreadImpl.getThreadInfo(ThreadImpl.java:461) at com.taobao.arthas.core.command.monitor200.ThreadCommand.processTopBusyThreads(ThreadCommand.java:206) at com.taobao.arthas.core.command.monitor200.ThreadCommand.process(ThreadCommand.java:122) at com.taobao.arthas.core.shell.command.impl.AnnotatedCommandImpl.process(AnnotatedCommandImpl.java:82) at com.taobao.arthas.core.shell.command.impl.AnnotatedCommandImpl.access$100(AnnotatedCommandImpl.java:18) at com.taobao.arthas.core.shell.command.impl.AnnotatedCommandImpl$ProcessHandler.handle(AnnotatedCommandImpl.java:111) at com.taobao.arthas.core.shell.command.impl.AnnotatedCommandImpl$ProcessHandler.handle(AnnotatedCommandImpl.java:108) at com.taobao.arthas.core.shell.system.impl.ProcessImpl$CommandProcessTask.run(ProcessImpl.java:385) at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) at java.util.concurrent.FutureTask.run(FutureTask.java:266) at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) 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:750) GC日志当线上应用因为堆内存空间不足而引起频繁Full GC时，同样会导致CPU占用持续高的问题。如果经过排查线程堆栈信息无法定位到具体的原因，就要转换思路，需要定位是否出现了Full GC。 在排查是否出现了频繁Full GC问题时，可以从2个方面入手：GC日志，JVM内存信息。 查看GC日志有多种方式，可以使用JDK自带的jstat命令查看实时的GC信息，也可以在启动参数中指定输出GC日志到到文件中。 jstat命令查看GC概要使用jstat命令可以试试查看JVM堆内存状态以及GC信息，命令语法为：jstat -gcutil ，如下示例： $ jstat -gcutil 34444 1000 S0 S1 E O M CCS YGC YGCT FGC FGCT GCT 0.00 34.38 13.91 53.31 93.42 86.18 427 0.770 5 0.348 1.119 0.00 34.38 13.91 53.31 93.42 86.18 427 0.770 5 0.348 1.119 0.00 34.38 13.91 53.31 93.42 86.18 427 0.770 5 0.348 1.119 0.00 34.38 33.96 53.31 93.42 86.18 427 0.770 5 0.348 1.119 0.00 34.38 33.96 53.31 93.42 86.18 427 0.770 5 0.348 1.119 0.00 34.38 33.96 53.31 93.42 86.18 427 0.770 5 0.348 1.119输出参数含义： S0: 新生代中Survivor space 0区已使用空间的百分比 S1: 新生代中Survivor space 1区已使用空间的百分比 E: 新生代已使用空间的百分比 O: 老年代已使用空间的百分比 M: 元空间已使用空间的百分比 CCS: Compressed class space utilization as a percentage YGC: 从应用程序启动到当前，发生Yang GC 的次数 YGCT: 从应用程序启动到当前，Yang GC所用的时间（单位：秒） FGC: 从应用程序启动到当前，发生Full GC的次数 FGCT: 从应用程序启动到当前，Full GC所用的时间 GCT: 从应用程序启动到当前，用于垃圾回收的总时间（单位：秒） GC日志文件使用JDK自带的jstat命令只能查看GC的概要信息，如果希望知道更加具体的GC细节，应该在应用启动参数中指定生成gc.log日志文件。 参数格式为：-Xloggc:/tmp/gc.log -XX:+PrintGCDetails -XX:+PrintGCDateStamps，相关参数含义如下： -Xloggc:/tmp/gc.log 日志文件的输出路径 -XX:+PrintGC 输出GC日志 -XX:+PrintGCDetails 输出GC的详细日志 -XX:+PrintGCTimeStamps 输出GC的时间戳（以基准时间的形式） -XX:+PrintGCDateStamps 输出GC的时间戳（以日期的形式，如2013-05-04T21:53:59.234+0800） -XX:+PrintHeapAtGC 在进行GC的前后打印出堆的信息如果是因为出现频繁Full GC导致的CPU占用高，那么在gc日志文件中将可以看到打印如下Full GC日志： 2024-06-14T11:02:52.151+0800: 613.966: [Full GC (Ergonomics) [PSYoungGen: 3584K->3583K(7168K)] [ParOldGen: 22009K->22009K(22016K)] 25593K->25593K(29184K), [Metaspace: 13892K->13892K(1071104K)], 0.0376547 secs] [Times: user=0.13 sys=0.00, real=0.04 secs] 2024-06-14T11:02:52.189+0800: 614.004: [Full GC (Ergonomics) [PSYoungGen: 3583K->3583K(7168K)] [ParOldGen: 22009K->22008K(22016K)] 25593K->25592K(29184K), [Metaspace: 13892K->13892K(1071104K)], 0.0419170 secs] [Times: user=0.15 sys=0.00, real=0.04 secs] 2024-06-14T11:02:52.231+0800: 614.046: [Full GC (Ergonomics) [PSYoungGen: 3584K->3583K(7168K)] [ParOldGen: 22008K->22008K(22016K)] 25592K->25592K(29184K), [Metaspace: 13892K->13892K(1071104K)], 0.0453520 secs] [Times: user=0.15 sys=0.00, real=0.05 secs] 2024-06-14T11:02:52.276+0800: 614.091: [Full GC (Ergonomics) [PSYoungGen: 3584K->3583K(7168K)] [ParOldGen: 22008K->22008K(22016K)] 25592K->25592K(29184K), [Metaspace: 13892K->13892K(1071104K)], 0.0397477 secs] [Times: user=0.14 sys=0.00, real=0.04 secs] 2024-06-14T11:02:52.316+0800: 614.131: [Full GC (Ergonomics) [PSYoungGen: 3584K->3584K(7168K)] [ParOldGen: 22008K->22008K(22016K)] 25592K->25592K(29184K), [Metaspace: 13892K->13892K(1071104K)], 0.0336829 secs] [Times: user=0.11 sys=0.00, real=0.03 secs] 内存dump Arthas工具memory命令还可以通过Arthas诊断工具的memory命令查看JVM内存信息。 $ memory Memory used total max usage heap 77M 136M 1762M 4.43% ps_eden_space 20M 42M 626M 3.23% ps_survivor_space 5M 17M 17M 30.53% ps_old_gen 52M 77M 1321M 3.98% nonheap 65M 66M -1 98.30% code_cache 10M 10M 240M 4.17% metaspace 49M 50M -1 98.26% compressed_class_space 6M 6M 1024M 0.63% direct 0K 0K - 0.00% mapped 0K 0K - 0.00% 堆内存dump文件不论使用JDK自带的jstat命令还是使用Arthas工具的memory命令，都只能查看到JVM堆内存的概要信息，并不利于排查和定位代码问题。如果是因为堆内存空间不足导致OutOfMemoryError报错，定位问题最好的办法是生成堆内存dump文件，然后再使用MAT工具进行分析，找到问题的根本原因并解决。 生成堆dump文件至少有三种方式： 其一：在启动参数中指定生成dump文件的时机和路径，如：-XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/tmp/headpdump.hprof 其二：使用JDk自带的jmap命令导出指定Java进程的堆内存dump文件，如：jmap -dump:file=/tmp/dump.hprof 其三：使用Arthas工具的heapdump命令将当前堆内存快照保存到文件中，如：heapdump /tmp/dump.hprof 第一种方式只有在Java进程出现OutOfMemoryError报错之后才会生成dump文件，而通过JDK提供的jmap命令或Arthas工具的heapdump命令方式可以随时生成堆dump文件，特别是出现频繁Full GC的时候导出堆内存dump文件非常有利于定位和解决问题。 此外，在使用MAT工具分析堆内存dump文件时，首先要关注的就是大对象有哪些。
排查Java进程CPU占用高的问题，基本思路如下： 首先，从线程堆栈入手，排查可能存在的代码死循环问题，可用的工具：JDK自带的jstack命令，Arthas工具的thread命令。 其次，如果线程堆栈中定位不到具体的原因，再去看看gc日志是否出现了频繁Full GC的问题，可用的工具：JDK自带的jstat命令，Arthas工具的memory命令。 最后，如果出现了频繁Full GC的问题，则使用JDK自带的jmap命令或者Arthas工具的heapdump命令导出堆内存文件，使用MAT工具进行分析和定位代码问题。 另外，为了方便线上排查问题，应该将相关的工具一起打到操作系统镜像中，这样在遇到线上故障时就不会手忙脚乱了。 附 jstack命令用法 $ jstack -help Usage: jstack [-l] (to connect to running process) jstack -F [-m] [-l] (to connect to a hung process) jstack [-m] [-l] (to connect to a core file) jstack [-m] [-l] [server_id@] (to connect to a remote debug server) Options: -F to force a thread dump. Use when jstack does not respond (process is hung) -m to print both java and native frames (mixed mode) -l long listing. Prints additional information about locks -h or -help to print this help message jstat命令用法 $ jstat -help Usage: jstat -help|-options jstat - [-t] [-h] [ []] Definitions: An option reported by the -options option Virtual Machine Identifier. A vmid takes the following form: [@[:]] Where is the local vm identifier for the target Java virtual machine, typically a process id; is the name of the host running the target Java virtual machine; and is the port number for the rmiregistry on the target host. See the jvmstat documentation for a more complete description of the Virtual Machine Identifier. Number of samples between header lines. Sampling interval. The following forms are allowed: ["ms"|"s"] Where is an integer and the suffix specifies the units as milliseconds("ms") or seconds("s"). The default units are "ms". Number of samples to take before terminating. -J Pass directly to the runtime system. jmap命令用法 $ jmap -help Usage: jmap [option] (to connect to running process) jmap [option] |
【本文地址】
今日新闻 |
推荐新闻 |