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         else
   8                 printf("WARNING: Cannot locate debugid for '%s'\n", codename)
   9         end
  10 end
  11
  12 initial_timestamp = 0
  13 workqueue_ptr_map = {};
  14 get_prefix = function(buf)
  15         if initial_timestamp == 0 then
  16                 initial_timestamp = buf.timestamp
  17         end
  18         local secs = trace.convert_timestamp_to_nanoseconds(buf.timestamp - initial_timestamp) / 1000000000
  19
  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
  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)
  41 end
  42
  43 parse_pthread_priority = function(pri)
  44         pri = pri & 0xffffffff
  45         if (pri & 0x02000000) == 0x02000000 then
  46                 return "Manager"
  47         end
  48         local qos = (pri & 0x00ffff00) >> 8
  49         if qos == 0x20 then
  50                 return string.format("UInter[%x]", pri);
  51         elseif qos == 0x10 then
  52                 return string.format("UInit[%x]", pri);
  53         elseif qos == 0x08 then
  54                 return string.format("Dflt[%x]", pri);
  55         elseif qos == 0x04 then
  56                 return string.format("Util[%x]", pri);
  57         elseif qos == 0x02 then
  58                 return string.format("BG[%x]", pri);
  59         elseif qos == 0x01 then
  60                 return string.format("Maint[%x]", pri);
  61         elseif qos == 0x00 then
  62                 return string.format("Unsp[%x]", pri);
  63         else
  64                 return string.format("Unkn[%x]", pri);
  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)
 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
 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)
 160         if buf.arg2 & 0x1000000 ~= 0 then
 161                 printf("%s\tworkqueue overcommitted @ %s, starting timer (thactive_count: %d, busycount; %d)\n",
 162                         prefix, parse_pthread_priority(buf.arg2), buf.arg3, buf.arg4)
 163         else
 164                 printf("%s\tworkqueue overcommitted @ %s (thactive_count: %d, busycount; %d)\n",
 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
 180                         printf("%s\ttrying to run a request on an idle thread (idlecount: %d, reqcount: %d)\n",
 181                                 prefix, buf.arg3, buf.arg4)
 182                 else
 183                         printf("%s\tthread %x looking for next request (idlecount: %d, reqcount: %d)\n",
 184                                 prefix, buf.threadid, buf.arg3, buf.arg4)
 185                 end
 186         else
 187                 if buf.arg4 == 1 then
 188                         printf("%s\tkicked off work on thread %x (overcommit: %d)\n", prefix, buf.arg2, buf.arg3)
 189                 elseif buf.arg4 == 3 then
 190                         printf("%s\tno work %x can currently do (start_timer: %d)\n", prefix, buf.arg2, buf.arg3)
 191                 elseif buf.arg4 == 4 then
 192                         printf("%s\treturning to run next item\n", prefix)
 193                 else
 194                         printf("%s\tWARNING: UNKNOWN END CODE:%d\n", prefix, buf.arg4)
 195                 end
 196         end
 197 end)
 198
 199 trace.enable_thread_cputime()
 200 runitem_time_map = {}
 201 runitem_cputime_map = {}
 202 trace_codename("wq_runitem", function(buf)
 203         local prefix = get_prefix(buf)
 204         if trace.debugid_is_start(buf.debugid) then
 205                 runitem_time_map[buf.threadid] = buf.timestamp;
 206                 runitem_cputime_map[buf.threadid] = trace.cputime_for_thread(buf.threadid);
 207
 208                 printf("%s\tSTART running item\n", prefix)
 209         elseif runitem_time_map[buf.threadid] then
 210                 local time = buf.timestamp - runitem_time_map[buf.threadid]
 211                 local cputime = trace.cputime_for_thread(buf.threadid) - runitem_cputime_map[buf.threadid]
 212
 213                 local time_ms = trace.convert_timestamp_to_nanoseconds(time) / 1000000
 214                 local cputime_ms = trace.convert_timestamp_to_nanoseconds(cputime) / 1000000
 215
 216                 printf("%s\tDONE running item: time = %6.6f ms, cputime = %6.6f ms\n", prefix, time_ms, cputime_ms)
 217
 218                 runitem_time_map[buf.threadid] = 0
 219                 runitem_cputime_map[buf.threadid] = 0
 220         else
 221                 printf("%s\tDONE running item\n", prefix)
 222         end
 223 end)
 224
 225 trace_codename("wq_thread_yielded", function(buf)
 226         local prefix = get_prefix(buf)
 227         if trace.debugid_is_start(buf.debugid) then
 228                 printf("%s\tthread_yielded called (yielded_count: %d, reqcount: %d)\n",
 229                         prefix, buf.arg2, buf.arg3)
 230         else
 231                 if buf.arg4 == 1 then
 232                         printf("%s\tthread_yielded completed kicking thread (yielded_count: %d, reqcount: %d)\n",
 233                                 prefix, buf.arg2, buf.arg3)
 234                 elseif buf.arg4 == 2 then
 235                         printf("%s\tthread_yielded completed (yielded_count: %d, reqcount: %d)\n",
 236                                 prefix, buf.arg2, buf.arg3)
 237                 else
 238                         printf("%s\tthread_yielded completed unusually (yielded_count: %d, reqcount: %d)\n",
 239                                 prefix, buf.arg2, buf.arg3)
 240                 end
 241         end
 242 end)
 243
 244 trace_codename("wq_thread_block", function(buf)
 245         local prefix = get_prefix(buf)
 246         if trace.debugid_is_start(buf.debugid) then
 247                 printf("%s\tthread blocked (activecount: %d, prioritiy: %d, start_time: %d)\n",
 248                         prefix, buf.arg2, buf.arg3, buf.arg3)
 249         else
 250                 printf("%s\tthread unblocked (threads_scheduled: %d, priority: %d)\n",
 251                         prefix, buf.arg2, buf.arg3)
 252         end
 253 end)
 254
 255 trace_codename("wq_thread_suspend", function(buf)
 256         local prefix = get_prefix(buf)
 257         if trace.debugid_is_start(buf.debugid) then
 258                 printf("%s\tcreated new suspended thread (nthreads:%d)\n",
 259                         prefix, buf.arg2)
 260         else
 261                 if buf.arg4 == 0xdead then
 262                         printf("%s\tthread exited suspension to die (nthreads: %d)\n",
 263                                 prefix, buf.arg3)
 264                 end
 265         end
 266 end)
 267
 268 trace_codename("wq_thread_park", function(buf)
 269         local prefix = get_prefix(buf)
 270         if trace.debugid_is_start(buf.debugid) then
 271                 printf("%s\tthread parked (threads_scheduled: %d, thidlecount: %d, us_to_wait: %d)\n",
 272                         prefix, buf.arg2, buf.arg3, buf.arg4)
 273         else
 274                 if buf.arg4 == 0xdead then
 275                         printf("%s\tthread exited park to die (nthreads: %d)\n", prefix, buf.arg3)
 276                 end
 277         end
 278
 279 end)
 280
 281 trace_codename("wq_thread_limit_exceeded", function(buf)
 282         local prefix = get_prefix(buf)
 283         printf("%s\ttotal thread limit exceeded, %d threads, total %d max threads, (kern limit: %d)\n",
 284                 prefix, buf.arg2, buf.arg3, buf.arg4)
 285 end)
 286
 287 trace_codename("wq_thread_constrained_maxed", function(buf)
 288         local prefix = get_prefix(buf)
 289         printf("%s\tattempted to add thread at max constrained limit, total %d threads (limit: %d)\n",
 290                 prefix, buf.arg2, buf.arg3)
 291 end)
 292
 293 trace_codename("wq_thread_add_during_exit", function(buf)
 294         local prefix = get_prefix(buf)
 295         printf("%s\tattempted to add thread during WQ_EXITING\n", prefix)
 296 end)
 297
 298 trace_codename("wq_thread_create_failed", function(buf)
 299         local prefix = get_prefix(buf)
 300         if buf.arg3 == 0 then
 301                 printf("%s\tfailed to create new workqueue thread, kern_return: 0x%x\n",
 302                         prefix, buf.arg2)
 303         elseif buf.arg3 == 1 then
 304                 printf("%s\tfailed to vm_map workq thread stack: 0x%x", prefix, buf.arg2)
 305         elseif buf.arg3 == 2 then
 306                 printf("%s\tfailed to vm_protect workq thread guardsize: 0x%x", prefix, buf.arg2)
 307         end
 308 end)
 309
 310 trace_codename("wq_thread_create", function(buf)
 311         printf("%s\tcreateed new workqueue thread\n", get_prefix(buf))
 312 end)
 313
 314 trace_codename("wq_manager_request", function(buf)
 315         local prefix = get_prefix(buf)
 316         printf("%s\tthread in bucket %d\n", prefix, buf.arg3)
 317 end)
 318
 319
 320 -- The trace codes we need aren't enabled by default
 321 darwin.sysctlbyname("kern.pthread_debug_tracing", 1)
 322 completion_handler = function()
 323         darwin.sysctlbyname("kern.pthread_debug_tracing", 0)
 324 end
 325 trace.set_completion_handler(completion_handler)