Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

funcgraph, funcslower, functrace: Make -p switch respect all the process' threads #55

Merged
merged 3 commits into from
Sep 5, 2017
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Jump to
Jump to file
Failed to load files.
Diff view
Diff view
3 changes: 2 additions & 1 deletion examples/funcgraph_example.txt
Original file line number Diff line number Diff line change
Expand Up @@ -2155,7 +2155,7 @@ performance investigation.
Use -h to print the USAGE message:

# ./funcgraph -h
USAGE: funcgraph [-aCDhHPtT] [-m maxdepth] [-p PID] [-d secs] funcstring
USAGE: funcgraph [-aCDhHPtT] [-m maxdepth] [-p PID] [-L TID] [-d secs] funcstring
-a # all info (same as -HPt)
-C # measure on-CPU time only
-d seconds # trace duration, and use buffers
Expand All @@ -2164,6 +2164,7 @@ USAGE: funcgraph [-aCDhHPtT] [-m maxdepth] [-p PID] [-d secs] funcstring
-H # include column headers
-m maxdepth # max stack depth to show
-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
-T # comment function tails
Expand Down
1 change: 1 addition & 0 deletions examples/funcslower_example.txt
Original file line number Diff line number Diff line change
Expand Up @@ -101,6 +101,7 @@ USAGE: funcslower [-aChHPt] [-p PID] [-d secs] funcstring latency_us
-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,
Expand Down
3 changes: 2 additions & 1 deletion examples/functrace_example.txt
Original file line number Diff line number Diff line change
Expand Up @@ -325,11 +325,12 @@ and events were missed.
Use -h to print the USAGE message:

# ./functrace -h
USAGE: functrace [-hH] [-p PID] [-d secs] funcstring
USAGE: functrace [-hH] [-p PID] [-L TID] [-d secs] funcstring
-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
eg,
functrace do_nanosleep # trace the do_nanosleep() function
functrace '*sleep' # trace functions ending in "sleep"
Expand Down
31 changes: 22 additions & 9 deletions kernel/funcgraph
Original file line number Diff line number Diff line change
Expand Up @@ -9,7 +9,7 @@
# using other, lower overhead tools. This is a proof of concept using Linux
# ftrace capabilities on older kernels.
#
# USAGE: funcgraph [-aCDhHPtT] [-m maxdepth] [-p PID] [-d secs] funcstring
# USAGE: funcgraph [-aCDhHPtT] [-m maxdepth] [-p PID] [-L TID] [-d secs] funcstring
#
# Run "funcgraph -h" for full usage.
#
Expand Down Expand Up @@ -68,14 +68,14 @@
### 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_tail=0; opt_nodur=0; opt_cpu=0
opt_duration=0; duration=; opt_pid=0; pid=; opt_tid=0; tid=; pidtext=
opt_headers=0; opt_proc=0; opt_time=0; opt_tail=0; opt_nodur=0; opt_cpu=0
opt_max=0; max=0
trap ':' INT QUIT TERM PIPE HUP # sends execution to end tracing section

function usage {
cat <<-END >&2
USAGE: funcgraph [-aCDhHPtT] [-m maxdepth] [-p PID] [-d secs] funcstring
USAGE: funcgraph [-aCDhHPtT] [-m maxdepth] [-p PID] [-L TID] [-d secs] funcstring
-a # all info (same as -HPt)
-C # measure on-CPU time only
-d seconds # trace duration, and use buffers
Expand All @@ -84,6 +84,7 @@ function usage {
-H # include column headers
-m maxdepth # max stack depth to show
-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
-T # comment function tails
Expand Down Expand Up @@ -118,7 +119,7 @@ function end {
(( opt_cpu )) && warn "echo sleep-time > trace_options"

warn "echo nop > current_tracer"
(( opt_pid )) && warn "echo > set_ftrace_pid"
(( opt_pid || opt_tid )) && warn "echo > set_ftrace_pid"
(( opt_max )) && warn "echo 0 > max_graph_depth"
warn "echo > set_graph_function"
warn "echo > trace"
Expand All @@ -140,7 +141,7 @@ function edie {
}

### process options
while getopts aCd:DhHm:p:PtT opt
while getopts aCd:DhHm:p:L:PtT opt
do
case $opt in
a) opt_headers=1; opt_proc=1; opt_time=1 ;;
Expand All @@ -149,6 +150,7 @@ do
D) opt_nodur=1; ;;
m) opt_max=1; max=$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; ;;
Expand All @@ -160,8 +162,10 @@ shift $(( $OPTIND - 1 ))

### option logic
(( $# == 0 )) && usage
(( opt_pid && opt_tid )) && edie "ERROR: You can use -p or -L but not both."
funcs="$1"
(( opt_pid )) && pidtext=" for PID $pid"
(( opt_tid )) && pidtext=" for TID $tid"
if (( opt_duration )); then
echo "Tracing \"$funcs\"$pidtext for $duration seconds..."
else
Expand All @@ -187,9 +191,18 @@ if (( opt_max )); then
fi
fi
if (( opt_pid )); then
if ! echo $pid > set_ftrace_pid; then
edie "ERROR: setting -p $pid (PID exist?). Exiting."
fi
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 > set_ftrace_filter; then
edie "ERROR: writing to set_ftrace_filter. Exiting."
Expand Down
27 changes: 20 additions & 7 deletions kernel/funcslower
Original file line number Diff line number Diff line change
Expand Up @@ -53,19 +53,20 @@
### 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
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] [-d secs] funcstring latency_us
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,
Expand Down Expand Up @@ -116,13 +117,14 @@ function edie {
}

### process options
while getopts aCd:hHp:Pt opt
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; ;;
Expand All @@ -133,10 +135,12 @@ 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..."
Expand Down Expand Up @@ -175,9 +179,18 @@ 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
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."
Expand Down
30 changes: 22 additions & 8 deletions kernel/functrace
Original file line number Diff line number Diff line change
Expand Up @@ -5,7 +5,7 @@
#
# This is a proof of concept using Linux ftrace capabilities on older kernels.
#
# USAGE: functrace [-hH] [-p PID] [-d secs] funcstring
# USAGE: functrace [-hH] [-p PID] [-L TID] [-d secs] funcstring
# eg,
# functrace '*sleep' # trace all functions ending in "sleep"
#
Expand Down Expand Up @@ -59,16 +59,18 @@
### 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_duration=0; duration=; opt_pid=0; pid=; opt_tid=0; tid=; pidtext=
opt_headers=0
trap ':' INT QUIT TERM PIPE HUP # sends execution to end tracing section

function usage {
cat <<-END >&2
USAGE: functrace [-hH] [-p PID] [-d secs] funcstring
USAGE: functrace [-hH] [-p PID] [-L TID] [-d secs] funcstring
-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
eg,
functrace do_nanosleep # trace the do_nanosleep() function
functrace '*sleep' # trace functions ending in "sleep"
Expand All @@ -93,7 +95,7 @@ function end {
echo "Ending tracing..." 2>/dev/null
cd $tracing
warn "echo nop > current_tracer"
(( opt_pid )) && warn "echo > set_ftrace_pid"
(( opt_pid || opt_tid )) && warn "echo > set_ftrace_pid"
warn "echo > set_ftrace_filter"
warn "echo > trace"
(( wroteflock )) && warn "rm $flock"
Expand All @@ -113,11 +115,12 @@ function edie {
}

### process options
while getopts d:hHp: opt
while getopts d:hHp:L: opt
do
case $opt in
d) opt_duration=1; duration=$OPTARG ;;
p) opt_pid=1; pid=$OPTARG ;;
L) opt_tid=1; tid=$OPTARG ;;
H) opt_headers=1; ;;
h|?) usage ;;
esac
Expand All @@ -126,8 +129,10 @@ shift $(( $OPTIND - 1 ))

### option logic
(( $# == 0 )) && usage
(( opt_pid && opt_tid )) && edie "ERROR: You can use -p or -L but not both."
funcs="$1"
(( opt_pid )) && pidtext=" for PID $pid"
(( opt_tid )) && pidtext=" for TID $pid"
if (( opt_duration )); then
echo "Tracing \"$funcs\"$pidtext for $duration seconds..."
else
Expand All @@ -148,9 +153,18 @@ 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 (( opt_pid )); then
if ! echo $pid > set_ftrace_pid; then
edie "ERROR: setting -p $pid (PID exist?). Exiting."
fi
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\". Exiting."
Expand Down
5 changes: 4 additions & 1 deletion man/man8/funcgraph.8
Original file line number Diff line number Diff line change
Expand Up @@ -3,7 +3,7 @@
funcgraph \- trace kernel function graph, showing child function calls and times. Uses Linux ftrace.
.SH SYNOPSIS
.B funcgraph
[\-aCDhHPtT] [\-m maxdepth] [\-p PID] [\-d secs] funcstring
[\-aCDhHPtT] [\-m maxdepth] [\-p PID] [\-L TID] [\-d secs] funcstring
.SH DESCRIPTION
This is an exploratory tool that shows the graph of child function calls
for a given kernel function. This can cost moderate overhead to execute, and
Expand Down Expand Up @@ -66,6 +66,9 @@ available for newer Linux kernel versions.
\-p PID
Only trace kernel functions when this process ID is on-CPU.
.TP
\-L TID
Only trace kernel functions when this thread ID is on-CPU.
.TP
\-P
Show process names and process IDs with every line of output.
.TP
Expand Down
5 changes: 4 additions & 1 deletion man/man8/funcslower.8
Original file line number Diff line number Diff line change
Expand Up @@ -3,7 +3,7 @@
funcslower \- trace kernel functions slower than a threshold (microseconds). Uses Linux ftrace.
.SH SYNOPSIS
.B funcslower
[\-aChHPt] [\-p PID] [\-d secs] funcstring latency_us
[\-aChHPt] [\-p PID] [\-L TID] [\-d secs] funcstring latency_us
.SH DESCRIPTION
This uses the Linux ftrace function graph profiler to time kernel functions
and filter them based on a latency threshold. Latency outliers can be studied
Expand Down Expand Up @@ -49,6 +49,9 @@ Print column headers.
\-p PID
Only trace kernel functions when this process ID is on-CPU.
.TP
\-L TID
Only trace kernel functions when this thread ID is on-CPU.
.TP
\-P
Show process names and process IDs with every line of output.
.TP
Expand Down
5 changes: 4 additions & 1 deletion man/man8/functrace.8
Original file line number Diff line number Diff line change
Expand Up @@ -3,7 +3,7 @@
functrace \- trace kernel function calls matching specified wildcards. Uses Linux ftrace.
.SH SYNOPSIS
.B functrace
[\-hH] [\-p PID] [\-d secs] funcstring
[\-hH] [\-p PID] [\-L TID] [\-d secs] funcstring
.SH DESCRIPTION
This tool provides a quick way to capture the execution of kernel functions,
showing basic details including as the process ID, timestamp, and calling
Expand Down Expand Up @@ -45,6 +45,9 @@ Print column headers.
\-p PID
Only trace kernel functions when this process ID is on-CPU.
.TP
\-L TID
Only trace kernel functions when this thread ID is on-CPU.
.TP
funcstring
A function name to trace, which may include file glob style wildcards ("*") at
the beginning or ending of a string only. Eg, "vfs*" means match "vfs" followed
Expand Down