用于快速排查Java的CPU性能问题(top us值过高)

转载于GIT路径 https://github.com/oldratlee/useful-scripts/blob/master/docs/java.md#beer-show-busy-java-threadssh

show-busy-java-threads.sh

用于快速排查Java的CPU性能问题(top us值过高)，自动查出运行的Java进程中消耗CPU多的线程，并打印出其线程栈，从而确定导致性能问题的方法调用。
目前只支持Linux。原因是Mac、Windows的ps命令不支持列出线程线程，更多信息参见#33，欢迎提供解法。

PS，如何操作可以参见@bluedavy的《分布式Java应用》的【5.1.1 cpu消耗分析】一节，说得很详细：

top命令找出有问题Java进程及线程id：
1. 开启线程显示模式
2. 按CPU使用率排序
3. 记下Java进程id及其CPU高的线程id
用进程id作为参数，jstack有问题的Java进程
手动转换线程id成十六进制（可以用printf %x 1234）
查找十六进制的线程id（可以用grep）
查看对应的线程栈

查问题时，会要多次这样操作以确定问题，上面过程太繁琐太慢了。

用法

show-busy-java-threads.sh
# 从所有运行的Java进程中找出最消耗CPU的线程（缺省5个），打印出其线程栈

# 缺省会自动从所有的Java进程中找出最消耗CPU的线程，这样用更方便
# 当然你可以手动指定要分析的Java进程Id，以保证只会显示出那个你关心的Java进程的信息
show-busy-java-threads.sh -p <指定的Java进程Id>

show-busy-java-threads.sh -c <要显示的线程栈数>

show-busy-java-threads.sh <重复执行的间隔秒数> [<重复执行的次数>]
# 多次执行；这2个参数的使用方式类似vmstat命令

show-busy-java-threads.sh -a <输出记录到的文件>
# 记录到文件以方便回溯查看

##############################
# 注意：
##############################
# 如果Java进程的用户 与 执行脚本的当前用户 不同，则jstack不了这个Java进程
# 为了能切换到Java进程的用户，需要加sudo来执行，即可以解决：
sudo show-busy-java-threads.sh

show-busy-java-threads.sh -s <指定jstack命令的全路径>
# 对于sudo方式的运行，JAVA_HOME环境变量不能传递给root，
# 而root用户往往没有配置JAVA_HOME且不方便配置，
# 显式指定jstack命令的路径就反而显得更方便了

# -m选项：执行jstack命令时加上-m选项，显示上Native的栈帧，一般应用排查不需要使用
show-busy-java-threads.sh -m
# -l选项：执行jstack命令时加上 -l 选项，显示上更多相关锁的信息，一般情况不需要使用
# 注意：和 -m -F 选项一起使用时，可能会大大增加jstack操作的耗时
show-busy-java-threads.sh -l
# -F选项：执行jstack命令时加上 -F 选项（如果直接jstack无响应时，用于强制jstack），一般情况不需要使用
show-busy-java-threads.sh -F

# 帮助信息
$ show-busy-java-threads.sh -h
Usage: show-busy-java-threads.sh [OPTION]... [delay [count]]
Find out the highest cpu consumed threads of java, and print the stack of these threads.

Example:
  show-busy-java-threads.sh       # show busy java threads info
  show-busy-java-threads.sh 1     # update every 1 seconds, (stop by eg: CTRL+C)
  show-busy-java-threads.sh 3 10  # update every 3 seconds, update 10 times

Options:
  -p, --pid <java pid>      find out the highest cpu consumed threads from the specifed java process,
                            default from all java process.
  -c, --count <num>         set the thread count to show, default is 5
  -a, --append-file <file>  specify the file to append output as log
  -s, --jstack-path <path>  specify the path of jstack command
  -F, --force               set jstack to force a thread dump
                            use when jstack <pid> does not respond (process is hung)
  -m, --mix-native-frames   set jstack to print both java and native frames (mixed mode)
  -l, --lock-info           set jstack with long listing. Prints additional information about locks
  -h, --help                display this help and exit
  delay                     the delay between updates in seconds
  count                     the number of updates
                            delay/count arguments imitates style of vmstat command

示例

$ show-busy-java-threads.sh
[1] Busy(57.0%) thread(23355/0x5b3b) stack of java process(23269) under user(admin):
"pool-1-thread-1" prio=10 tid=0x000000005b5c5000 nid=0x5b3b runnable [0x000000004062c000]
   java.lang.Thread.State: RUNNABLE
    at java.text.DateFormat.format(DateFormat.java:316)
    at com.xxx.foo.services.common.DateFormatUtil.format(DateFormatUtil.java:41)
    at com.xxx.foo.shared.monitor.schedule.AppMonitorDataAvgScheduler.run(AppMonitorDataAvgScheduler.java:127)
    at com.xxx.foo.services.common.utils.AliTimer$2.run(AliTimer.java:128)
    at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
    at java.lang.Thread.run(Thread.java:662)

[2] Busy(26.1%) thread(24018/0x5dd2) stack of java process(23269) under user(admin):
"pool-1-thread-2" prio=10 tid=0x000000005a968800 nid=0x5dd2 runnable [0x00000000420e9000]
   java.lang.Thread.State: RUNNABLE
    at java.util.Arrays.copyOf(Arrays.java:2882)
    at java.lang.AbstractStringBuilder.expandCapacity(AbstractStringBuilder.java:100)
    at java.lang.AbstractStringBuilder.append(AbstractStringBuilder.java:572)
    at java.lang.StringBuffer.append(StringBuffer.java:320)
    - locked <0x00000007908d0030> (a java.lang.StringBuffer)
    at java.text.SimpleDateFormat.format(SimpleDateFormat.java:890)
    at java.text.SimpleDateFormat.format(SimpleDateFormat.java:869)
    at java.text.DateFormat.format(DateFormat.java:316)
    at com.xxx.foo.services.common.DateFormatUtil.format(DateFormatUtil.java:41)
    at com.xxx.foo.shared.monitor.schedule.AppMonitorDataAvgScheduler.run(AppMonitorDataAvgScheduler.java:126)
    at com.xxx.foo.services.common.utils.AliTimer$2.run(AliTimer.java:128)
    at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
...

上面的线程栈可以看出，CPU消耗最高的2个线程都在执行java.text.DateFormat.format，业务代码对应的方法是shared.monitor.schedule.AppMonitorDataAvgScheduler.run。可以基本确定：

AppMonitorDataAvgScheduler.run调用DateFormat.format次数比较频繁。
DateFormat.format比较慢。（这个可以由DateFormat.format的实现确定。）

多执行几次show-busy-java-threads.sh，如果上面情况高概率出现，则可以确定上面的判定。
# 因为调用越少代码执行越快，则出现在线程栈的概率就越低。
# 脚本有自动多次执行的功能，指定重复执行的间隔秒数/重复执行的次数参数。

分析shared.monitor.schedule.AppMonitorDataAvgScheduler.run实现逻辑和调用方式，以优化实现解决问题。

#!/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
# @author superhj1987

readonly PROG="`basename $0`"
readonly -a COMMAND_LINE=("$0" "$@")

# Check os support!
uname | grep '^Linux' -q || {
    echo "$PROG only support Linux, not support `uname` yet!" 1>&2
    exit 2
}

# Get corrent current user name via whoami command
#   See get https://www.lifewire.com/current-linux-user-whoami-command-3867579
# Because if use `sudo -u` to run command, env var $USER is not rewrited/correct, just inherited from outside!
readonly USER="`whoami`"

usage() {
    [ -n "$1" -a "$1" != 0 ] && local out=/dev/stderr || local out=/dev/stdout

    > $out cat <<EOF
Usage: ${PROG} [OPTION]... [delay [count]]
Find out the highest cpu consumed threads of java, and print the stack of these threads.
Example:
  ${PROG}       # show busy java threads info
  ${PROG} 1     # update every 1 seconds, (stop by eg: CTRL+C)
  ${PROG} 3 10  # update every 3 seconds, update 10 times
Options:
  -p, --pid <java pid>      find out the highest cpu consumed threads from the specifed java process,
                            default from all java process.
  -c, --count <num>         set the thread count to show, default is 5
  -a, --append-file <file>  specify the file to append output as log
  -s, --jstack-path <path>  specify the path of jstack command
  -F, --force               set jstack to force a thread dump
                            use when jstack <pid> does not respond (process is hung)
  -m, --mix-native-frames   set jstack to print both java and native frames (mixed mode)
  -l, --lock-info           set jstack with long listing. Prints additional information about locks
  -h, --help                display this help and exit
  delay                     the delay between updates in seconds
  count                     the number of updates
                            delay/count arguments imitates style of vmstat command
EOF

    exit $1
}

readonly ARGS=`getopt -n "$PROG" -a -o p:c:a:s:Fmlh -l count:,pid:,append-file:,jstack-path:,force,mix-native-frames,lock-info,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
        ;;
    -a|--append-file)
        append_file="$2"
        shift 2
        ;;
    -s|--jstack-path)
        jstack_path="$2"
        shift 2
        ;;
    -F|--force)
        force=-F
        shift 1
        ;;
    -m|--mix-native-frames)
        mix_native_frames=-m
        shift 1
        ;;
    -l|--lock-info)
        more_lock_info=-l
        shift 1
        ;;
    -h|--help)
        usage
        ;;
    --)
        shift
        break
        ;;
    esac
done
count=${count:-5}

update_delay=${1:-0}
[ -z "$1" ] && update_count=1 || update_count=${2:-0}
[ $update_count -lt 0 ] && update_count=0

# NOTE: $'foo' is the escape sequence syntax of bash
readonly ec=$'33' # escape char
readonly eend=$'33[0m' # escape end

colorPrint() {
    local color=$1
    shift
    if [ -c /dev/stdout ] ; then
        # if stdout is console, turn on color output.
        echo "$ec[1;${color}m$@$eend"
    else
        echo "$@"
    fi

    [ -n "$append_file" ] && echo "$@" >> "$append_file"
}

redPrint() {
    colorPrint 31 "$@"
}

greenPrint() {
    colorPrint 32 "$@"
}

yellowPrint() {
    colorPrint 33 "$@"
}

bluePrint() {
    colorPrint 36 "$@"
}

normalPrint() {
    echo "$@"

    [ -n "$append_file" ] && echo "$@" >> "$append_file"
}

if [ -n "$jstack_path" ]; then
    [ ! -x "$jstack_path" ] && {
        redPrint "Error: $jstack_path is NOT found/executalbe!" 1>&2
        exit 1
    }
elif which jstack &> /dev/null; then
    # Check the existence of jstack command!
    jstack_path="`which jstack`"
else
    [ -z "$JAVA_HOME" ] && {
        redPrint "Error: jstack not found on PATH! Use -s option set jstack path manually." 1>&2
        exit 1
    }
    [ ! -f "$JAVA_HOME/bin/jstack" ] && {
        redPrint "Error: jstack not found on PATH and $JAVA_HOME/bin/jstack($JAVA_HOME/bin/jstack) file does NOT exists! Use -s option set jstack path manually." 1>&2
        exit 1
    }
    [ ! -x "$JAVA_HOME/bin/jstack" ] && {
        redPrint "Error: jstack not found on PATH and $JAVA_HOME/bin/jstack($JAVA_HOME/bin/jstack) is NOT executalbe! Use -s option set jstack path manually." 1>&2
        exit 1
    }
    export PATH="$JAVA_HOME/bin:$PATH"
    jstack_path="`which jstack`"
fi

readonly uuid=`date +%s`_${RANDOM}_$$

cleanupWhenExit() {
    rm /tmp/${uuid}_* &> /dev/null
}
trap "cleanupWhenExit" EXIT

printStackOfThreads() {
    local line
    local counter=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_path" ${force} $mix_native_frames $more_lock_info ${pid} > ${jstackFile}
                elif [ $UID == 0 ]; then
                    sudo -u "${user}" "$jstack_path" ${force} $mix_native_frames $more_lock_info ${pid} > ${jstackFile}
                else
                    redPrint "[$((counter++))] Fail to jstack Busy(${pcpu}%) thread(${threadId}/${threadId0x}) stack of java process(${pid}) under user(${user})."
                    redPrint "User of java process($user) is not current user($USER), need sudo to run again:"
                    yellowPrint "    sudo ${COMMAND_LINE[@]}"
                    normalPrint
                    continue
                fi
            } || {
                redPrint "[$((counter++))] Fail to jstack Busy(${pcpu}%) thread(${threadId}/${threadId0x}) stack of java process(${pid}) under user(${user})."
                normalPrint
                rm ${jstackFile}
                continue
            }
        }

        bluePrint "[$((counter++))] Busy(${pcpu}%) thread(${threadId}/${threadId0x}) stack of java process(${pid}) under user(${user}):"

        if [ -n "$mix_native_frames" ]; then
            local sed_script="/------------- $threadId -------------/,/^---------------/ {
                /^---------------/b # skip seperator lines
                p
            }"
        elif [ -n "$force" ]; then
            local sed_script="/Thread $threadId:/,/^$/p"
        else
            local sed_script="/nid=${threadId0x} /,/^$/p"
        fi

        sed "$sed_script" -n ${jstackFile} | tee ${append_file:+-a "$append_file"}
    done
}

head_info() {
    echo ================================================================================
    echo "$(date "+%Y-%m-%d %H:%M:%S.%N") [$((i+1))/$update_count]: ${COMMAND_LINE[@]}"
    echo ================================================================================
    echo
}

# if update_count <= 0, infinite loop till user interupted (eg: CTRL+C)
for ((i = 0; update_count <= 0 || i < update_count; ++i)); do
    [ "$i" -gt 0 ] && sleep "$update_delay"

    [ -n "$append_file" ] && head_info >> "$append_file"
    [ "$update_count" -ne 1 ] && head_info

    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 -n "${count}" | printStackOfThreads
done