-
Notifications
You must be signed in to change notification settings - Fork 1.6k
/
funcslower
executable file
·248 lines (229 loc) · 7.4 KB
/
funcslower
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
181
182
183
184
185
186
187
188
189
190
191
192
193
194
195
196
197
198
199
200
201
202
203
204
205
206
207
208
209
210
211
212
213
214
215
216
217
218
219
220
221
222
223
224
225
226
227
228
229
230
231
232
233
234
235
236
237
238
239
240
241
242
243
244
245
246
247
248
#!/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.
#
# (https://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