tools/wqtrace.lua

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