funcslower

#!/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=; 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] [-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
	                 -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: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 ;;
	H)	opt_headers=1; ;;
	P)	opt_proc=1; ;;
	t)	opt_time=1; ;;
	h|?)	usage ;;
	esac
done
shift $(( $OPTIND - 1 ))

### option logic
(( $# < 2 )) && usage
funcs="$1"
shift
thresh=$1
(( opt_pid )) && pidtext=" for PID $pid"
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
	if ! echo $pid > set_ftrace_pid; then
		edie "ERROR: setting -p $pid (PID 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