Linux系统 CPU 100% 异常排查实践与总结
1、问题背景
昨天下午突然收到运维邮件报警，显示数据平台服务器 cpu 利用率达到了 98.94%，而且最近一段时间一直持续在 70% 以上，看起来像是硬件资源到瓶颈需要扩容了，但仔细思考就会发现咱们的业务系统并不是一个高并发或者 CPU 密集型的应用，这个利用率有点太夸张，硬件瓶颈应该不会这么快就到了，一定是哪里的业务代码逻辑有问题。
2、排查思路
2.1 定位高负载进程 pid
首先登录到服务器使用 top 命令确认服务器的具体情况，根据具体情况再进行分析判断。
通过观察 load average，以及负载评判标准（8 核），可以确认服务器存在负载较高的情况；
观察各个进程资源使用情况，可以看出进程 id 为 682 的进程，有着较高的 CPU 占比
2.2 定位具体的异常业务
这里咱们可以使用 pwdx 命令根据 pid 找到业务进程路径，进而定位到负责人和项目：
可得出结论：该进程对应的就是数据平台的 web 服务。
2.3 定位异常线程及具体代码行
传统的方案一般是 4 步：
- top oder by with P：1040 // 首先按进程负载排序找到 maxLoad (pid)
- top -Hp 进程 PID：1073 // 找到相关负载 线程 PID
- printf “0x% x\n” 线程 PID： 0x431 // 将线程 PID 转换为 16 进制，为后面查找 jstack 日志做准备
- jstack 进程 PID | vim +/ 十六进制线程 PID - // 例如：jstack 1040|vim +/0x431 -
但是对于线上问题定位来说，分秒必争，上面的 4 步还是太繁琐耗时了，之前介绍过淘宝的 oldratlee 同学就将上面的流程封装为了一个工具：show-busy-java-threads.sh，可以很方便的定位线上的这类问题：
可得出结论：是系统中一个时间工具类方法的执行 cpu 占比较高，定位到具体方法后，查看代码逻辑是否存在性能问题。
※ 如果线上问题比较紧急，可以省略 2.1、2.2 直接执行 2.3，这里从多角度剖析只是为了给大家呈现一个完整的分析思路。
3、根因分析
经过前面的分析与排查，最终定位到一个时间工具类的问题，造成了服务器负载以及 cpu 使用率的过高。
- 异常方法逻辑：是把时间戳转成对应的具体的日期时间格式；
- 上层调用：计算当天凌晨至当前时间所有秒数，转化成对应的格式放入到 set 中返回结果；
- 逻辑层：对应的是数据平台实时报表的查询逻辑，实时报表会按照固定的时间间隔来，并且在一次查询中有多次（n 次）方法调用。
那么可以得到结论，如果现在时间是当天上午 10 点，一次查询的计算次数就是 106060n 次 = 36,000n 次计算，而且随着时间增长，越接近午夜单次查询次数会线性增加。由于实时查询、实时报警等模块大量的查询请求都需要多次调用该方法，导致了大量 CPU 资源的占用与浪费。
4、解决方案
定位到问题之后，首先考虑是要减少计算次数，优化异常方法。排查后发现，在逻辑层使用时，并没有使用该方法返回的 set 集合中的内容，而是简单的用 set 的 size 数值。确认逻辑后，通过新方法简化计算（当前秒数 - 当天凌晨的秒数），替换调用的方法，解决计算过多的问题。上线后观察服务器负载和 cpu 使用率，对比异常时间段下降了 30 倍，恢复至正常状态，至此该问题得已解决。
5、总结
- 在编码的过程中，除了要实现业务的逻辑，也要注重代码性能的优化。一个业务需求，能实现，和能实现的更高效、更优雅其实是两种截然不同的工程师能力和境界的体现，而后者也是工程师的核心竞争力。
- 在代码编写完成之后，多做 review，多思考是不是可以用更好的方式来实现。
- 线上问题不放过任何一个小细节！细节是魔鬼，技术的同学需要有刨根问题的求知欲和追求卓越的精神，只有这样，才能不断的成长和提升。
附上show-busy-java-threads.sh脚本
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 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 100 101 102 103 104 105 106 107 108 109 110 111 112 113 114 115 116 117 118 119 120 121 122 123 124 125 126 127 128 129 130 131 132 133 134 135 136 137 138 139 140 141 142 143 144 145 146 147 148 | #!/bin/bash # @Function # Find out the highest cpu consumed threads of java, and print the stack of these threads. # # @Usage # $ ./show-busy-java-threads.sh # # @author Jerry Lee readonly PROG=`basename $0` readonly -a COMMAND_LINE=("$0" "$@") usage() { cat <<EOF Usage: ${PROG} [OPTION]... Find out the highest cpu consumed threads of java, and print the stack of these threads. Example: ${PROG} -c 10 Options: -p, --pid find out the highest cpu consumed threads from the specifed java process, default from all java process. -c, --count set the thread count to show, default is 5 -h, --help display this help and exit EOF exit $1 } readonly ARGS=`getopt -n "$PROG" -a -o c:p:h -l count:,pid:,help -- "$@"` [ $? -ne 0 ] && usage 1 eval set -- "${ARGS}" while true; do case "$1" in -c|--count) count="$2" shift 2 ;; -p|--pid) pid="$2" shift 2 ;; -h|--help) usage ;; --) shift break ;; esac done count=${count:-5} redEcho() { [ -c /dev/stdout ] && { # if stdout is console, turn on color output. echo -ne "\033[1;31m" echo -n "$@" echo -e "\033[0m" } || echo "$@" } yellowEcho() { [ -c /dev/stdout ] && { # if stdout is console, turn on color output. echo -ne "\033[1;33m" echo -n "$@" echo -e "\033[0m" } || echo "$@" } blueEcho() { [ -c /dev/stdout ] && { # if stdout is console, turn on color output. echo -ne "\033[1;36m" echo -n "$@" echo -e "\033[0m" } || echo "$@" } # Check the existence of jstack command! if ! which jstack &> /dev/null; then [ -z "$JAVA_HOME" ] && { redEcho "Error: jstack not found on PATH!" exit 1 } ! [ -f "$JAVA_HOME/bin/jstack" ] && { redEcho "Error: jstack not found on PATH and $JAVA_HOME/bin/jstack file does NOT exists!" exit 1 } ! [ -x "$JAVA_HOME/bin/jstack" ] && { redEcho "Error: jstack not found on PATH and $JAVA_HOME/bin/jstack is NOT executalbe!" exit 1 } export PATH="$JAVA_HOME/bin:$PATH" fi readonly uuid=`date +%s`_${RANDOM}_$$ cleanupWhenExit() { rm /tmp/${uuid}_* &> /dev/null } trap "cleanupWhenExit" EXIT printStackOfThreads() { local line local count=1 while IFS=" " read -a line ; do local pid=${line[0]} local threadId=${line[1]} local threadId0x="0x`printf %x ${threadId}`" local user=${line[2]} local pcpu=${line[4]} local jstackFile=/tmp/${uuid}_${pid} [ ! -f "${jstackFile}" ] && { { if [ "${user}" == "${USER}" ]; then jstack ${pid} > ${jstackFile} else if [ $UID == 0 ]; then sudo -u ${user} jstack ${pid} > ${jstackFile} else redEcho "[$((count++))] Fail to jstack Busy(${pcpu}%) thread(${threadId}/${threadId0x}) stack of java process(${pid}) under user(${user})." redEcho "User of java process($user) is not current user($USER), need sudo to run again:" yellowEcho " sudo ${COMMAND_LINE[@]}" echo continue fi fi } || { redEcho "[$((count++))] Fail to jstack Busy(${pcpu}%) thread(${threadId}/${threadId0x}) stack of java process(${pid}) under user(${user})." echo rm ${jstackFile} continue } } blueEcho "[$((count++))] Busy(${pcpu}%) thread(${threadId}/${threadId0x}) stack of java process(${pid}) under user(${user}):" sed "/nid=${threadId0x} /,/^$/p" -n ${jstackFile} done } ps -Leo pid,lwp,user,comm,pcpu --no-headers | { [ -z "${pid}" ] && awk '$4=="java"{print $0}' || awk -v "pid=${pid}" '$1==pid,$4=="java"{print $0}' } | sort -k5 -r -n | head --lines "${count}" | printStackOfThreads |
参考
https://my.oschina.net/leejun2005/blog/1602482
https://mp.weixin.qq.com/s/e4UlRJprskJryDqAEYpNEw
[1] 线上服务 CPU 100%？一键定位 so easy！
https://my.oschina.net/leejun2005/blog/1524687
[2] 又一次生产 CPU 高负载排查实践
[3] linux 系统监控、诊断工具之 top 详解
