]>
Commit | Line | Data |
---|---|---|
964d3577 A |
1 | #!/usr/local/bin/luatrace -s |
2 | ||
3 | trace_codename = function(codename, callback) | |
4 | local debugid = trace.debugid(codename) | |
5 | if debugid ~= 0 then | |
6 | trace.single(debugid,callback) | |
2546420a A |
7 | else |
8 | printf("WARNING: Cannot locate debugid for '%s'\n", codename) | |
964d3577 A |
9 | end |
10 | end | |
11 | ||
12 | initial_timestamp = 0 | |
2546420a | 13 | workqueue_ptr_map = {}; |
964d3577 A |
14 | get_prefix = function(buf) |
15 | if initial_timestamp == 0 then | |
16 | initial_timestamp = buf.timestamp | |
17 | end | |
2546420a A |
18 | local secs = (buf.timestamp - initial_timestamp) / 1000000000 |
19 | ||
964d3577 A |
20 | local prefix |
21 | if trace.debugid_is_start(buf.debugid) then | |
22 | prefix = "→" | |
23 | elseif trace.debugid_is_end(buf.debugid) then | |
24 | prefix = "←" | |
25 | else | |
26 | prefix = "↔" | |
27 | end | |
2546420a A |
28 | |
29 | local proc | |
30 | if buf.command ~= "kernel_task" then | |
31 | proc = buf.command | |
32 | workqueue_ptr_map[buf[1]] = buf.command | |
33 | elseif workqueue_ptr_map[buf[1]] ~= nil then | |
34 | proc = workqueue_ptr_map[buf[1]] | |
35 | else | |
36 | proc = "UNKNOWN" | |
37 | end | |
38 | ||
39 | return string.format("%s %6.9f %-17s [%05d.%06x] %-24s", | |
40 | prefix, secs, proc, buf.pid, buf.threadid, buf.debugname) | |
964d3577 A |
41 | end |
42 | ||
43 | parse_pthread_priority = function(pri) | |
2546420a A |
44 | pri = pri & 0xffffffff |
45 | if (pri & 0x02000000) == 0x02000000 then | |
46 | return "Manager" | |
47 | end | |
48 | local qos = (pri & 0x00ffff00) >> 8 | |
964d3577 | 49 | if qos == 0x20 then |
2546420a | 50 | return string.format("UInter[%x]", pri); |
964d3577 | 51 | elseif qos == 0x10 then |
2546420a | 52 | return string.format("UInit[%x]", pri); |
964d3577 | 53 | elseif qos == 0x08 then |
2546420a | 54 | return string.format("Dflt[%x]", pri); |
964d3577 | 55 | elseif qos == 0x04 then |
2546420a | 56 | return string.format("Util[%x]", pri); |
964d3577 | 57 | elseif qos == 0x02 then |
2546420a | 58 | return string.format("BG[%x]", pri); |
964d3577 | 59 | elseif qos == 0x01 then |
2546420a | 60 | return string.format("Maint[%x]", pri); |
964d3577 | 61 | elseif qos == 0x00 then |
2546420a | 62 | return string.format("Unsp[%x]", pri); |
964d3577 | 63 | else |
2546420a | 64 | return string.format("Unkn[%x]", pri); |
964d3577 A |
65 | end |
66 | end | |
67 | ||
68 | -- workqueue lifecycle | |
69 | ||
70 | trace_codename("wq_pthread_exit", function(buf) | |
71 | local prefix = get_prefix(buf) | |
72 | if trace.debugid_is_start(buf.debugid) then | |
73 | printf("%s\tprocess is exiting\n",prefix) | |
74 | else | |
75 | printf("%s\tworkqueue marked as exiting and timer is complete\n",prefix) | |
76 | end | |
77 | end) | |
78 | ||
79 | trace_codename("wq_workqueue_exit", function(buf) | |
80 | local prefix = get_prefix(buf) | |
81 | if trace.debugid_is_start(buf.debugid) then | |
82 | printf("%s\tall threads have exited, cleaning up\n",prefix) | |
83 | else | |
84 | printf("%s\tclean up complete\n",prefix) | |
85 | end | |
86 | end) | |
87 | ||
88 | -- thread requests | |
89 | ||
90 | trace_codename("wq_kevent_req_threads", function(buf) | |
91 | local prefix = get_prefix(buf) | |
92 | if trace.debugid_is_start(buf.debugid) then | |
93 | printf("%s\tkevent requesting threads (requests[] length = %d)\n", prefix, buf.arg2) | |
94 | else | |
95 | printf("%s\tkevent request complete (start_timer: %d)\n", prefix, buf.arg2) | |
96 | end | |
97 | end) | |
98 | ||
99 | trace_codename("wq_req_threads", function(buf) | |
100 | local prefix = get_prefix(buf) | |
101 | printf("%s\trecording %d constrained request(s) at %s, total %d requests\n", | |
102 | prefix, buf.arg4, parse_pthread_priority(buf.arg2), buf.arg3) | |
103 | end) | |
104 | ||
105 | trace_codename("wq_req_octhreads", function(buf) | |
106 | local prefix = get_prefix(buf) | |
107 | printf("%s\tattempting %d overcommit request(s) at %s, total %d requests\n", | |
108 | prefix, buf.arg4, parse_pthread_priority(buf.arg2), buf.arg3) | |
109 | end) | |
110 | trace_codename("wq_delay_octhreads", function(buf) | |
111 | local prefix = get_prefix(buf) | |
112 | printf("%s\trecording %d delayed overcommit request(s) at %s, total %d requests\n", | |
113 | prefix, buf.arg4, parse_pthread_priority(buf.arg2), buf.arg3) | |
114 | end) | |
115 | ||
116 | trace_codename("wq_req_kevent_threads", function(buf) | |
117 | local prefix = get_prefix(buf) | |
118 | printf("%s\trecording kevent constrained request at %s, total %d requests\n", | |
119 | prefix, parse_pthread_priority(buf.arg2), buf.arg3) | |
120 | end) | |
121 | trace_codename("wq_req_kevent_octhreads", function(buf) | |
122 | local prefix = get_prefix(buf) | |
123 | printf("%s\trecording kevent overcommit request at %s, total %d requests\n", | |
124 | prefix, parse_pthread_priority(buf.arg2), buf.arg3) | |
125 | end) | |
126 | trace_codename("wq_req_event_manager", function(buf) | |
127 | local prefix = get_prefix(buf) | |
2546420a A |
128 | if buf.arg2 == 1 then |
129 | printf("%s\tstarting event manager thread, existing at %d, %d added\n", | |
130 | prefix, buf.arg3, buf.arg4) | |
131 | else | |
132 | printf("%s\trecording event manager request, existing at %d, %d added\n", | |
133 | prefix, buf.arg3, buf.arg4) | |
134 | end | |
964d3577 A |
135 | end) |
136 | ||
137 | trace_codename("wq_start_add_timer", function(buf) | |
138 | local prefix = get_prefix(buf) | |
139 | printf("%s\tarming timer to fire in %d us (flags: %x, reqcount: %d)\n", | |
140 | prefix, buf.arg4, buf.arg3, buf.arg2) | |
141 | end) | |
142 | ||
143 | trace_codename("wq_add_timer", function(buf) | |
144 | local prefix = get_prefix(buf) | |
145 | if trace.debugid_is_start(buf.debugid) then | |
146 | printf("%s\tadd_timer fired (flags: %x, nthreads: %d, thidlecount: %d)\n", | |
147 | prefix, buf.arg2, buf.arg3, buf.arg4) | |
148 | elseif trace.debugid_is_end(buf.debugid) then | |
149 | printf("%s\tadd_timer completed (start_timer: %x, nthreads: %d, thidlecount: %d)\n", | |
150 | prefix, buf.arg2, buf.arg3, buf.arg4) | |
151 | else | |
152 | printf("%s\tadd_timer added threads (reqcount: %d, thidlecount: %d, busycount: %d)\n", | |
153 | prefix, buf.arg2, buf.arg3, buf.arg4) | |
154 | ||
155 | end | |
156 | end) | |
157 | ||
158 | trace_codename("wq_overcommitted", function(buf) | |
159 | local prefix = get_prefix(buf) | |
2546420a A |
160 | if buf.arg2 & 0x1000000 ~= 0 then |
161 | printf("%s\tworkqueue overcommitted @ %s, starting timer (thactive_count: %d, busycount; %d)\n", | |
964d3577 A |
162 | prefix, parse_pthread_priority(buf.arg2), buf.arg3, buf.arg4) |
163 | else | |
2546420a | 164 | printf("%s\tworkqueue overcommitted @ %s (thactive_count: %d, busycount; %d)\n", |
964d3577 A |
165 | prefix, parse_pthread_priority(buf.arg2), buf.arg3, buf.arg4) |
166 | end | |
167 | end) | |
168 | ||
169 | trace_codename("wq_stalled", function(buf) | |
170 | local prefix = get_prefix(buf) | |
171 | printf("%s\tworkqueue stalled (nthreads: %d)\n", prefix, buf.arg3) | |
172 | end) | |
173 | ||
174 | -- thread lifecycle | |
175 | ||
176 | trace_codename("wq_run_nextitem", function(buf) | |
177 | local prefix = get_prefix(buf) | |
178 | if trace.debugid_is_start(buf.debugid) then | |
179 | if buf.arg2 == 0 then | |
964d3577 A |
180 | printf("%s\ttrying to run a request on an idle thread (idlecount: %d, reqcount: %d)\n", |
181 | prefix, buf.arg3, buf.arg4) | |
2546420a A |
182 | else |
183 | printf("%s\tthread %x looking for next request (idlecount: %d, reqcount: %d)\n", | |
184 | prefix, buf.threadid, buf.arg3, buf.arg4) | |
964d3577 A |
185 | end |
186 | else | |
187 | if buf.arg4 == 1 then | |
2546420a | 188 | printf("%s\tkicked off work on thread %x (overcommit: %d)\n", prefix, buf.arg2, buf.arg3) |
964d3577 | 189 | elseif buf.arg4 == 3 then |
2546420a | 190 | printf("%s\tno work %x can currently do (start_timer: %d)\n", prefix, buf.arg2, buf.arg3) |
964d3577 | 191 | elseif buf.arg4 == 4 then |
2546420a | 192 | printf("%s\treturning to run next item\n", prefix) |
964d3577 A |
193 | else |
194 | printf("%s\tWARNING: UNKNOWN END CODE:%d\n", prefix, buf.arg4) | |
195 | end | |
196 | end | |
197 | end) | |
198 | ||
199 | trace_codename("wq_runitem", function(buf) | |
200 | local prefix = get_prefix(buf) | |
201 | if trace.debugid_is_start(buf.debugid) then | |
2546420a | 202 | printf("%s\tSTART running item\n", prefix) |
964d3577 | 203 | else |
2546420a | 204 | printf("%s\tDONE running item; thread returned to kernel\n", prefix) |
964d3577 A |
205 | end |
206 | end) | |
207 | ||
208 | trace_codename("wq_thread_yielded", function(buf) | |
209 | local prefix = get_prefix(buf) | |
210 | if trace.debugid_is_start(buf.debugid) then | |
211 | printf("%s\tthread_yielded called (yielded_count: %d, reqcount: %d)\n", | |
212 | prefix, buf.arg2, buf.arg3) | |
213 | else | |
2546420a | 214 | if buf.arg4 == 1 then |
964d3577 A |
215 | printf("%s\tthread_yielded completed kicking thread (yielded_count: %d, reqcount: %d)\n", |
216 | prefix, buf.arg2, buf.arg3) | |
2546420a | 217 | elseif buf.arg4 == 2 then |
964d3577 A |
218 | printf("%s\tthread_yielded completed (yielded_count: %d, reqcount: %d)\n", |
219 | prefix, buf.arg2, buf.arg3) | |
220 | else | |
221 | printf("%s\tthread_yielded completed unusually (yielded_count: %d, reqcount: %d)\n", | |
222 | prefix, buf.arg2, buf.arg3) | |
223 | end | |
224 | end | |
225 | end) | |
226 | ||
227 | trace_codename("wq_thread_block", function(buf) | |
228 | local prefix = get_prefix(buf) | |
229 | if trace.debugid_is_start(buf.debugid) then | |
230 | printf("%s\tthread blocked (activecount: %d, prioritiy: %d, start_time: %d)\n", | |
231 | prefix, buf.arg2, buf.arg3, buf.arg3) | |
232 | else | |
233 | printf("%s\tthread unblocked (threads_scheduled: %d, priority: %d)\n", | |
234 | prefix, buf.arg2, buf.arg3) | |
235 | end | |
236 | end) | |
237 | ||
238 | trace_codename("wq_thread_suspend", function(buf) | |
239 | local prefix = get_prefix(buf) | |
240 | if trace.debugid_is_start(buf.debugid) then | |
241 | printf("%s\tcreated new suspended thread (nthreads:%d)\n", | |
242 | prefix, buf.arg2) | |
243 | else | |
244 | if buf.arg4 == 0xdead then | |
245 | printf("%s\tthread exited suspension to die (nthreads: %d)\n", | |
246 | prefix, buf.arg3) | |
247 | end | |
248 | end | |
249 | end) | |
250 | ||
251 | trace_codename("wq_thread_park", function(buf) | |
252 | local prefix = get_prefix(buf) | |
253 | if trace.debugid_is_start(buf.debugid) then | |
254 | printf("%s\tthread parked (threads_scheduled: %d, thidlecount: %d, us_to_wait: %d)\n", | |
255 | prefix, buf.arg2, buf.arg3, buf.arg4) | |
256 | else | |
257 | if buf.arg4 == 0xdead then | |
258 | printf("%s\tthread exited park to die (nthreads: %d)\n", prefix, buf.arg3) | |
259 | end | |
260 | end | |
261 | ||
262 | end) | |
263 | ||
264 | trace_codename("wq_thread_limit_exceeded", function(buf) | |
265 | local prefix = get_prefix(buf) | |
266 | printf("%s\ttotal thread limit exceeded, %d threads, total %d max threads, (kern limit: %d)\n", | |
267 | prefix, buf.arg2, buf.arg3, buf.arg4) | |
268 | end) | |
269 | ||
270 | trace_codename("wq_thread_constrained_maxed", function(buf) | |
271 | local prefix = get_prefix(buf) | |
272 | printf("%s\tattempted to add thread at max constrained limit, total %d threads (limit: %d)\n", | |
273 | prefix, buf.arg2, buf.arg3) | |
274 | end) | |
275 | ||
276 | trace_codename("wq_thread_add_during_exit", function(buf) | |
277 | local prefix = get_prefix(buf) | |
278 | printf("%s\tattempted to add thread during WQ_EXITING\n", prefix) | |
279 | end) | |
280 | ||
281 | trace_codename("wq_thread_create_failed", function(buf) | |
282 | local prefix = get_prefix(buf) | |
283 | if buf.arg3 == 0 then | |
284 | printf("%s\tfailed to create new workqueue thread, kern_return: 0x%x\n", | |
285 | prefix, buf.arg2) | |
286 | elseif buf.arg3 == 1 then | |
287 | printf("%s\tfailed to vm_map workq thread stack: 0x%x", prefix, buf.arg2) | |
288 | elseif buf.arg3 == 2 then | |
289 | printf("%s\tfailed to vm_protect workq thread guardsize: 0x%x", prefix, buf.arg2) | |
290 | end | |
291 | end) | |
292 | ||
2546420a A |
293 | trace_codename("wq_thread_create", function(buf) |
294 | printf("%s\tcreateed new workqueue thread\n", get_prefix(buf)) | |
295 | end) | |
296 | ||
297 | trace_codename("wq_manager_request", function(buf) | |
298 | local prefix = get_prefix(buf) | |
299 | printf("%s\tthread in bucket %d\n", prefix, buf.arg3) | |
300 | end) | |
301 | ||
964d3577 A |
302 | |
303 | -- The trace codes we need aren't enabled by default | |
304 | darwin.sysctlbyname("kern.pthread_debug_tracing", 1) | |
305 | completion_handler = function() | |
306 | darwin.sysctlbyname("kern.pthread_debug_tracing", 0) | |
307 | end | |
308 | trace.set_completion_handler(completion_handler) |