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
|
#!/usr/bin/awk -f
#
# This program generates collapsed off-cpu stacks fit for use by flamegraph.pl
# from scheduler data collected via perf_events.
#
# Outputs the cumulative time off cpu in us for each distinct stack observed.
#
# Some awk variables further control behavior:
#
# record_tid If truthy, causes all stack traces to include the
# command and LWP id.
#
# record_wake_stack If truthy, stacks include the frames from the wakeup
# event in addition to the sleep event.
# See http://www.brendangregg.com/FlameGraphs/offcpuflamegraphs.html#Wakeup
#
# recurse If truthy, attempt to recursively identify and
# visualize the full wakeup stack chain.
# See http://www.brendangregg.com/FlameGraphs/offcpuflamegraphs.html#ChainGraph
#
# Note that this is only an approximation, as only the
# last sleep event is recorded (e.g. if a thread slept
# multiple times before waking another thread, only the
# last sleep event is used). Implies record_wake_stack=1
#
# To set any of these variables from the command line, run via:
#
# stackcollapse-perf-sched.awk -v recurse=1
#
# == Important warning ==
#
# WARNING: tracing all scheduler events is very high overhead in perf. Even
# more alarmingly, there appear to be bugs in perf that prevent it from reliably
# getting consistent traces (even with large trace buffers), causing it to
# produce empty perf.data files with error messages of the form:
#
# 0x952790 [0x736d]: failed to process type: 3410
#
# This failure is not determinisitic, so re-executing perf record will
# eventually succeed.
#
# == Usage ==
#
# First, record data via perf_events:
#
# sudo perf record -g -e 'sched:sched_switch' \
# -e 'sched:sched_stat_sleep' -e 'sched:sched_stat_blocked' \
# -p <pid> -o perf.data -- sleep 1
#
# Then post process with this script:
#
# sudo perf script -f time,comm,pid,tid,event,ip,sym,dso,trace -i perf.data | \
# stackcollapse-perf-sched.awk -v recurse=1 | \
# flamegraph.pl --color=io --countname=us >out.svg
#
#
# CDDL HEADER START
#
# The contents of this file are subject to the terms of the
# Common Development and Distribution License (the "License").
# You may not use this file except in compliance with the License.
#
# You can obtain a copy of the license at docs/cddl1.txt or
# http://opensource.org/licenses/CDDL-1.0.
# See the License for the specific language governing permissions
# and limitations under the License.
#
# When distributing Covered Code, include this CDDL HEADER in each
# file and include the License file at docs/cddl1.txt.
# If applicable, add the following below this CDDL HEADER, with the
# fields enclosed by brackets "[]" replaced with your own identifying
# information: Portions Copyright [yyyy] [name of copyright owner]
#
# CDDL HEADER END
#
#
# Copyright (c) 2015 by MemSQL. All rights reserved.
#
#
# Match a perf captured variable, returning just the contents. For example, for
# the following line, get_perf_captured_variable("pid") would return "27235":
#
# swapper 0 [006] 708189.626415: sched:sched_stat_sleep: comm=memsqld pid=27235 delay=100078421 [ns
#
function get_perf_captured_variable(variable)
{
match($0, variable "=[^[:space:]]+")
return substr($0, RSTART + length(variable) + 1,
RLENGTH - length(variable) - 1)
}
#
# The timestamp is the first field that ends in a colon, e.g.:
#
# swapper 0 [006] 708189.626415: sched:sched_stat_sleep: comm=memsqld pid=27235 delay=100078421 [ns
#
# or
#
# swapper 0/0 708189.626415: sched:sched_stat_sleep: comm=memsqld pid=27235 delay=100078421 [ns]
#
function get_perf_timestamp()
{
match($0, " [^ :]+:")
return substr($0, RSTART + 1, RLENGTH - 2)
}
!/^#/ && /sched:sched_switch/ {
switchcommand = get_perf_captured_variable("comm")
switchpid = get_perf_captured_variable("prev_pid")
switchtime=get_perf_timestamp()
switchstack=""
}
#
# Strip the function name from a stack entry
#
# Stack entry is expected to be formatted like:
# c60849 MyClass::Foo(unsigned long) (/home/areece/a.out)
#
function get_function_name()
{
# We start from 2 since we don't need the hex offset.
# We stop at NF - 1 since we don't need the library path.
funcname = $2
for (i = 3; i <= NF - 1; i++) {
funcname = funcname " " $i
}
return funcname
}
(switchpid != 0 && /^[[:space:]]/) {
if (switchstack == "") {
switchstack = get_function_name()
} else {
switchstack = get_function_name() ";" switchstack
}
}
(switchpid != 0 && /^$/) {
switch_stacks[switchpid] = switchstack
delete last_switch_stacks[switchpid]
switch_time[switchpid] = switchtime
switchpid=0
switchcommand=""
switchstack=""
}
!/^#/ && (/sched:sched_stat_sleep/ || /sched:sched_stat_blocked/) {
wakecommand=$1
wakepid=$2
waketime=get_perf_timestamp()
stat_next_command = get_perf_captured_variable("comm")
stat_next_pid = get_perf_captured_variable("pid")
stat_delay_ns = int(get_perf_captured_variable("delay"))
wakestack=""
}
(stat_next_pid != 0 && /^[[:space:]]/) {
if (wakestack == "") {
wakestack = get_function_name()
} else {
# We build the wakestack in reverse order.
wakestack = wakestack ";" get_function_name()
}
}
(stat_next_pid != 0 && /^$/) {
#
# For some reason, perf appears to output duplicate
# sched:sched_stat_sleep and sched:sched_stat_blocked events. We only
# handle the first event.
#
if (stat_next_pid in switch_stacks) {
last_wake_time[stat_next_pid] = waketime
stack = switch_stacks[stat_next_pid]
if (recurse || record_wake_stack) {
stack = stack ";" wakestack
if (record_tid) {
stack = stack ";" wakecommand "-" wakepid
} else {
stack = stack ";" wakecommand
}
}
if (recurse) {
if (last_wake_time[wakepid] > last_switch_time[stat_next_pid]) {
stack = stack ";-;" last_switch_stacks[wakepid]
}
last_switch_stacks[stat_next_pid] = stack
}
delete switch_stacks[stat_next_pid]
if (record_tid) {
stack_times[stat_next_command "-" stat_next_pid ";" stack] += stat_delay_ns
} else {
stack_times[stat_next_command ";" stack] += stat_delay_ns
}
}
wakecommand=""
wakepid=0
stat_next_pid=0
stat_next_command=""
stat_delay_ms=0
}
END {
for (stack in stack_times) {
if (int(stack_times[stack] / 1000) > 0) {
print stack, int(stack_times[stack] / 1000)
}
}
}
|
