#!/bin/bash # # funcslower - trace kernel functions slower than a threshold (microseconds). # Uses Linux ftrace. # # This uses the Linux ftrace function graph profiler to time kernel functions # and filter them based on a latency threshold. This is a proof of concept using # Linux ftrace capabilities on older kernels. # # USAGE: funcslower [-aChHPt] [-p PID] [-d secs] funcstring latency_us # # Run "funcslower -h" for full usage. # # REQUIREMENTS: FTRACE function graph, which you may already have available # and enabled in recent kernels. And awk. # # The output format is the same as the ftrace function graph trace format, # described in the kernel source under Documentation/trace/ftrace.txt. # Note that the output may be shuffled when different CPU buffers are read; # check the CPU column for changes, or include timestamps (-t) and post sort. # # WARNING: This uses dynamic tracing of kernel functions, and could cause # kernel panics or freezes. Test, and know what you are doing, before use. # # OVERHEADS: Timing and filtering is performed in-kernel context, costing # lower overheads than post-processing in user space. If you trace frequent # events (eg, pick a common function and a low threshold), you might want to # try the "-d secs" option, which buffers events in-kernel instead of printing # them live. # # From perf-tools: https://github.com/brendangregg/perf-tools # # COPYRIGHT: Copyright (c) 2014 Brendan Gregg. # # This program is free software; you can redistribute it and/or # modify it under the terms of the GNU General Public License # as published by the Free Software Foundation; either version 2 # of the License, or (at your option) any later version. # # This program is distributed in the hope that it will be useful, # but WITHOUT ANY WARRANTY; without even the implied warranty of # MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the # GNU General Public License for more details. # # You should have received a copy of the GNU General Public License # along with this program; if not, write to the Free Software Foundation, # Inc., 59 Temple Place - Suite 330, Boston, MA 02111-1307, USA. # # (http://www.gnu.org/copyleft/gpl.html) # # 12-Jul-2014 Brendan Gregg Created this. ### default variables tracing=/sys/kernel/debug/tracing flock=/var/tmp/.ftrace-lock opt_duration=0; duration=; opt_pid=0; pid=; opt_tid=0; tid= pidtext=; opt_headers=0; opt_proc=0; opt_time=0; opt_cpu=0 trap ':' INT QUIT TERM PIPE HUP # sends execution to end tracing section function usage { cat <<-END >&2 USAGE: funcslower [-aChHPt] [-p PID] [-L TID] [-d secs] funcstring latency_us -a # all info (same as -HPt) -C # measure on-CPU time only -d seconds # trace duration, and use buffers -h # this usage message -H # include column headers -p PID # trace when this pid is on-CPU -L TID # trace when this thread is on-CPU -P # show process names & PIDs -t # show timestamps eg, funcslower vfs_read 10000 # trace vfs_read() slower than 10 ms See the man page and example file for more info. END exit } function warn { if ! eval "$@"; then echo >&2 "WARNING: command failed \"$@\"" fi } function end { # disable tracing echo 2>/dev/null echo "Ending tracing..." 2>/dev/null cd $tracing (( opt_time )) && warn "echo nofuncgraph-abstime > trace_options" (( opt_proc )) && warn "echo nofuncgraph-proc > trace_options" (( opt_cpu )) && warn "echo sleep-time > trace_options" warn "echo nop > current_tracer" (( opt_pid )) && warn "echo > set_ftrace_pid" warn "echo > set_ftrace_filter" warn "echo > set_graph_function" warn "echo 0 > tracing_thresh" warn "echo > trace" (( wroteflock )) && warn "rm $flock" } function die { echo >&2 "$@" exit 1 } function edie { # die with a quiet end() echo >&2 "$@" exec >/dev/null 2>&1 end exit 1 } ### process options while getopts aCd:hHp:L:Pt opt do case $opt in a) opt_headers=1; opt_proc=1; opt_time=1 ;; C) opt_cpu=1; ;; d) opt_duration=1; duration=$OPTARG ;; p) opt_pid=1; pid=$OPTARG ;; L) opt_tid=1; tid=$OPTARG ;; H) opt_headers=1; ;; P) opt_proc=1; ;; t) opt_time=1; ;; h|?) usage ;; esac done shift $(( $OPTIND - 1 )) ### option logic (( $# < 2 )) && usage (( opt_pid && opt_tid )) && edie "ERROR: You can use -p or -L but not both." funcs="$1" shift thresh=$1 (( opt_pid )) && pidtext=" for PID $pid" (( opt_tid )) && pidtext=" for TID $tid" printf "Tracing \"$funcs\"$pidtext slower than $thresh us" if (( opt_duration )); then echo " for $duration seconds..." else echo "... Ctrl-C to end." fi ## select awk if (( opt_duration )); then [[ -x /usr/bin/mawk ]] && awk=mawk || awk=awk else # workarounds for mawk/gawk fflush behavior if [[ -x /usr/bin/gawk ]]; then awk=gawk elif [[ -x /usr/bin/mawk ]]; then awk="mawk -W interactive" else awk=awk fi fi ### check permissions cd $tracing || die "ERROR: accessing tracing. Root user? Kernel has FTRACE? debugfs mounted? (mount -t debugfs debugfs /sys/kernel/debug)" ### ftrace lock [[ -e $flock ]] && die "ERROR: ftrace may be in use by PID $(cat $flock) $flock" echo $$ > $flock || die "ERROR: unable to write $flock." wroteflock=1 ### setup and commence tracing sysctl -q kernel.ftrace_enabled=1 # doesn't set exit status read mode < current_tracer [[ "$mode" != "nop" ]] && edie "ERROR: ftrace active (current_tracer=$mode)" if ! echo $thresh > tracing_thresh; then edie "ERROR: setting tracing_thresh to $thresh. Exiting." fi if (( opt_pid )); then echo '' > set_ftrace_pid # ftrace expects kernel pids, which are thread ids for tid in /proc/$pid/task/*; do if ! echo ${tid##*/} >> set_ftrace_pid; then edie "ERROR: setting -p $pid (PID exist?). Exiting." fi done fi if (( opt_tid )); then if ! echo $tid > set_ftrace_pid; then edie "ERROR: setting -L $tid (TID exist?). Exiting." fi fi if ! echo "$funcs" > set_ftrace_filter; then edie "ERROR: enabling \"$funcs\" filter. Function exist? Exiting." fi if ! echo "$funcs" > set_graph_function; then edie "ERROR: enabling \"$funcs\" graph. Exiting." fi if ! echo function_graph > current_tracer; then edie "ERROR: setting current_tracer to \"function_graph\". Exiting." fi if (( opt_cpu )); then if ! echo nosleep-time > trace_options; then edie "ERROR: setting -C (nosleep-time). Exiting." fi fi # the following must be done after setting current_tracer if (( opt_time )); then if ! echo funcgraph-abstime > trace_options; then edie "ERROR: setting -t (funcgraph-abstime). Exiting." fi fi if (( opt_proc )); then if ! echo funcgraph-proc > trace_options; then edie "ERROR: setting -P (funcgraph-proc). Exiting." fi fi ### setup output filter cat=cat if (( opt_proc )); then # remove proc change entries, since PID is included. example: # ------------------------------------------ # 0) supervi-1699 => supervi-1693 # ------------------------------------------ # cat=$awk' "/(^ ---|^$)/ || \$3 == \"=>\" { next } { print \$0 }"' fi ### print trace buffer warn "echo > trace" if (( opt_duration )); then sleep $duration if (( opt_headers )); then $cat trace else $cat trace | grep -v '^#' fi else # trace_pipe lack headers, so fetch them from trace (( opt_headers )) && cat trace eval $cat trace_pipe fi ### end tracing end