用於快速排查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消耗分析】一節，說得很詳細：

1. top命令找出有問題Java進程及線程id：
   1. 開啟線程顯示模式
   2. 按CPU使用率排序
   3. 記下Java進程id及其CPU高的線程id
2. 用進程id作為參數，jstack有問題的Java進程
3. 手動轉換線程id成十六進制（可以用printf %x 1234）
4. 查找十六進制的線程id（可以用grep）
5. 查看對應的線程棧

查問題時，會要多次這樣操作以確定問題，上面過程太繁瑣太慢了。

用法

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=$'\033' # escape char
readonly eend=$'\033[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