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("UI[%x]", pri);
  51         elseif qos == 0x10 then
  52                 return string.format("IN[%x]", pri);
  53         elseif qos == 0x08 then
  54                 return string.format("DF[%x]", pri);
  55         elseif qos == 0x04 then
  56                 return string.format("UT[%x]", pri);
  57         elseif qos == 0x02 then
  58                 return string.format("BG[%x]", pri);
  59         elseif qos == 0x01 then
  60                 return string.format("MT[%x]", pri);
  61         elseif qos == 0x00 then
  62                 return string.format("--[%x]", pri);
  63         else
  64                 return string.format("??[%x]", pri);
  65         end
  66 end
  67
  68 parse_qos_bucket = function(pri)
  69         if pri == 0 then
  70                 return string.format("UI[%x]", pri);
  71         elseif pri == 1 then
  72                 return string.format("IN[%x]", pri);
  73         elseif pri == 2 then
  74                 return string.format("DF[%x]", pri);
  75         elseif pri == 3 then
  76                 return string.format("UT[%x]", pri);
  77         elseif pri == 4 then
  78                 return string.format("BG[%x]", pri);
  79         elseif pri == 5 then
  80                 return string.format("MT[%x]", pri);
  81         elseif pri == 6 then
  82                 return string.format("MG[%x]", pri);
  83         else
  84                 return string.format("??[%x]", pri);
  85         end
  86 end
  87
  88 parse_thactive_req_bucket = function(pri)
  89     if pri ~= 6 then
  90         return parse_qos_bucket(pri)
  91     end
  92     return "None"
  93 end
  94
  95 get_thactive = function(low, high)
  96     return string.format("req: %s, MG: %d, UI: %d, IN: %d, DE: %d, UT: %d, BG: %d, MT: %d",
  97            parse_thactive_req_bucket(high >> (16 * 3)), (high >> (2 * 16)) & 0xffff,
  98            (low  >> (0 * 16)) & 0xffff, (low  >> (1 * 16)) & 0xffff,
  99            (low  >> (2 * 16)) & 0xffff, (low  >> (3 * 16)) & 0xffff,
 100            (high >> (0 * 16)) & 0xffff, (high >> (1 * 16)) & 0xffff)
 101 end
 102
 103 -- workqueue lifecycle
 104
 105 trace_codename("wq_pthread_exit", function(buf)
 106         local prefix = get_prefix(buf)
 107         if trace.debugid_is_start(buf.debugid) then
 108                 printf("%s\tprocess is exiting\n",prefix)
 109         else
 110                 printf("%s\tworkqueue marked as exiting and timer is complete\n",prefix)
 111         end
 112 end)
 113
 114 trace_codename("wq_workqueue_exit", function(buf)
 115         local prefix = get_prefix(buf)
 116         if trace.debugid_is_start(buf.debugid) then
 117                 printf("%s\tall threads have exited, cleaning up\n",prefix)
 118         else
 119                 printf("%s\tclean up complete\n",prefix)
 120         end
 121 end)
 122
 123 trace_codename("wq_start_add_timer", function(buf)
 124         local prefix = get_prefix(buf)
 125         printf("%s\tarming timer to fire in %d us (flags: %x, reqcount: %d)\n",
 126                 prefix, buf.arg4, buf.arg3, buf.arg2)
 127 end)
 128
 129 trace_codename("wq_add_timer", function(buf)
 130         local prefix = get_prefix(buf)
 131         if trace.debugid_is_start(buf.debugid) then
 132                 printf("%s\tadd_timer fired (flags: %x, nthreads: %d, thidlecount: %d)\n",
 133                         prefix, buf.arg2, buf.arg3, buf.arg4)
 134         elseif trace.debugid_is_end(buf.debugid) then
 135                 printf("%s\tadd_timer completed (start_timer: %x, nthreads: %d, thidlecount: %d)\n",
 136                         prefix, buf.arg2, buf.arg3, buf.arg4)
 137         else
 138                 printf("%s\tadd_timer added threads (reqcount: %d, thidlecount: %d, busycount: %d)\n",
 139                         prefix, buf.arg2, buf.arg3, buf.arg4)
 140
 141         end
 142 end)
 143
 144 trace_codename("wq_run_threadreq", function(buf)
 145         local prefix = get_prefix(buf)
 146         if trace.debugid_is_start(buf.debugid) then
 147                 if buf[2] > 0 then
 148                         printf("%s\trun_threadreq: %x (priority: %s, flags: %d) on %x\n",
 149                                         prefix, buf[2], parse_qos_bucket(buf[4] >> 16), buf[4] & 0xff, buf[3])
 150                 else
 151                         printf("%s\trun_threadreq: <none> on %x\n",
 152                                         prefix, buf[3])
 153                 end
 154         else
 155                 if buf[2] == 1 then
 156                         printf("%s\tpended event manager, already running\n", prefix)
 157                 elseif buf[2] == 2 then
 158                         printf("%s\tnothing to do\n", prefix)
 159                 elseif buf[2] == 3 then
 160                         printf("%s\tno eligible request found\n", prefix)
 161                 elseif buf[2] == 4 then
 162                         printf("%s\tadmission control failed\n", prefix)
 163                 elseif buf[2] == 5 then
 164                         printf("%s\tunable to add new thread (may_add_new_thread: %d, nthreads: %d)\n", prefix, buf[3], buf[4])
 165                 elseif buf[2] == 6 then
 166                         printf("%s\tthread creation failed\n", prefix)
 167                 elseif buf[2] == 0 then
 168                         printf("%s\tsuccess\n", prefix)
 169                 else
 170                         printf("%s\tWARNING: UNKNOWN END CODE:%d\n", prefix, buf.arg4)
 171                 end
 172         end
 173 end)
 174
 175 trace_codename("wq_run_threadreq_mgr_merge", function(buf)
 176         local prefix = get_prefix(buf)
 177         printf("%s\t\tmerging incoming manager request into existing\n", prefix)
 178 end)
 179
 180 trace_codename("wq_run_threadreq_req_select", function(buf)
 181         local prefix = get_prefix(buf)
 182         if buf[3] == 1 then
 183                 printf("%s\t\tselected event manager request %x\n", prefix, buf[2])
 184         elseif buf[3] == 2 then
 185                 printf("%s\t\tselected overcommit request %x\n", prefix, buf[2])
 186         elseif buf[3] == 3 then
 187                 printf("%s\t\tselected constrained request %x\n", prefix, buf[2])
 188         else
 189                 printf("%s\t\tWARNING: UNKNOWN DECISION CODE:%d\n", prefix, buf.arg[3])
 190         end
 191 end)
 192
 193 trace_codename("wq_run_threadreq_thread_select", function(buf)
 194         local prefix = get_prefix(buf)
 195         if buf[2] == 1 then
 196                 printf("%s\t\trunning on current thread %x\n", prefix, buf[3])
 197         elseif buf[2] == 2 then
 198                 printf("%s\t\trunning on idle thread %x\n", prefix, buf[3])
 199         elseif buf[2] == 3 then
 200                 printf("%s\t\tcreated new thread\n", prefix)
 201         else
 202                 printf("%s\t\tWARNING: UNKNOWN DECISION CODE:%d\n", prefix, buf.arg[2])
 203         end
 204 end)
 205
 206 trace_codename("wq_thread_reset_priority", function(buf)
 207         local prefix = get_prefix(buf)
 208         local old_qos = buf[3] >> 16;
 209         local new_qos = buf[3] & 0xff;
 210         if buf[4] == 1 then
 211                 printf("%s\t\treset priority of %x from %s to %s\n", prefix, buf[2], parse_qos_bucket(old_qos), parse_qos_bucket(new_qos))
 212         elseif buf[4] == 2 then
 213                 printf("%s\t\treset priority of %x from %s to %s for reserve manager\n", prefix, buf[2], parse_qos_bucket(old_qos), parse_qos_bucket(new_qos))
 214         elseif buf[4] == 3 then
 215                 printf("%s\t\treset priority of %x from %s to %s for cleanup\n", prefix, buf[2], parse_qos_bucket(old_qos), parse_qos_bucket(new_qos))
 216         end
 217 end)
 218
 219 trace_codename("wq_thread_park", function(buf)
 220         local prefix = get_prefix(buf)
 221         if trace.debugid_is_start(buf.debugid) then
 222                 printf("%s\tthread parking\n", prefix)
 223         else
 224                 printf("%s\tthread woken\n", prefix)
 225         end
 226 end)
 227
 228 trace_codename("wq_thread_squash", function(buf)
 229         local prefix = get_prefix(buf)
 230         printf("%s\tthread squashed from %s to %s\n", prefix,
 231                         parse_qos_bucket(buf[2]), parse_qos_bucket(buf[3]))
 232 end)
 233
 234 trace.enable_thread_cputime()
 235 runitem_time_map = {}
 236 runitem_cputime_map = {}
 237 trace_codename("wq_runitem", function(buf)
 238         local prefix = get_prefix(buf)
 239         if trace.debugid_is_start(buf.debugid) then
 240                 runitem_time_map[buf.threadid] = buf.timestamp;
 241                 runitem_cputime_map[buf.threadid] = trace.cputime_for_thread(buf.threadid);
 242
 243                 printf("%s\tSTART running item @ %s\n", prefix, parse_qos_bucket(buf[3]))
 244         elseif runitem_time_map[buf.threadid] then
 245                 local time = buf.timestamp - runitem_time_map[buf.threadid]
 246                 local cputime = trace.cputime_for_thread(buf.threadid) - runitem_cputime_map[buf.threadid]
 247
 248                 local time_ms = trace.convert_timestamp_to_nanoseconds(time) / 1000000
 249                 local cputime_ms = trace.convert_timestamp_to_nanoseconds(cputime) / 1000000
 250
 251                 printf("%s\tDONE running item @ %s: time = %6.6f ms, cputime = %6.6f ms\n",
 252                                 prefix, parse_qos_bucket(buf[2]), time_ms, cputime_ms)
 253
 254                 runitem_time_map[buf.threadid] = 0
 255                 runitem_cputime_map[buf.threadid] = 0
 256         else
 257                 printf("%s\tDONE running item @ %s\n", prefix, parse_qos_bucket(buf[2]))
 258         end
 259 end)
 260
 261 trace_codename("wq_runthread", function(buf)
 262         local prefix = get_prefix(buf)
 263         if trace.debugid_is_start(buf.debugid) then
 264                 printf("%s\tSTART running thread\n", prefix)
 265         elseif trace.debugid_is_end(buf.debugid) then
 266                 printf("%s\tDONE running thread\n", prefix)
 267         end
 268 end)
 269
 270 trace_codename("wq_thactive_update", function(buf)
 271     local prefix = get_prefix(buf)
 272     local thactive = get_thactive(buf[2], buf[3])
 273     if buf[1] == 1 then
 274         printf("%s\tthactive constrained pre-post (%s)\n", prefix, thactive)
 275     elseif buf[1] == 2 then
 276         printf("%s\tthactive constrained run (%s)\n", prefix, thactive)
 277     else
 278         return
 279     end
 280 end)
 281
 282 trace_codename("wq_thread_block", function(buf)
 283         local prefix = get_prefix(buf)
 284         local req_pri = parse_thactive_req_bucket(buf[3] >> 8)
 285         if trace.debugid_is_start(buf.debugid) then
 286                 printf("%s\tthread blocked (activecount: %d, priority: %s, req_pri: %s, reqcount: %d, start_timer: %d)\n",
 287                         prefix, buf[2], parse_qos_bucket(buf[3] & 0xff), req_pri, buf[4] >> 1, buf[4] & 0x1)
 288         else
 289                 printf("%s\tthread unblocked (activecount: %d, priority: %s, req_pri: %s, threads_scheduled: %d)\n",
 290                         prefix, buf[2], parse_qos_bucket(buf[3] & 0xff), req_pri, buf[4])
 291         end
 292 end)
 293
 294 trace_codename("wq_thread_create_failed", function(buf)
 295         local prefix = get_prefix(buf)
 296         if buf[3] == 0 then
 297                 printf("%s\tfailed to create new workqueue thread, kern_return: 0x%x\n",
 298                         prefix, buf[2])
 299         elseif buf[3] == 1 then
 300                 printf("%s\tfailed to vm_map workq thread stack: 0x%x\n", prefix, buf[2])
 301         elseif buf[3] == 2 then
 302                 printf("%s\tfailed to vm_protect workq thread guardsize: 0x%x\n", prefix, buf[2])
 303         end
 304 end)
 305
 306 trace_codename("wq_thread_create", function(buf)
 307         printf("%s\tcreated new workqueue thread\n", get_prefix(buf))
 308 end)
 309
 310 trace_codename("wq_wqops_reqthreads", function(buf)
 311         local prefix = get_prefix(buf)
 312         printf("%s\tuserspace requested %d threads at %s\n", prefix, buf[2], parse_pthread_priority(buf[3]));
 313 end)
 314
 315 trace_codename("wq_kevent_reqthreads", function(buf)
 316         local prefix = get_prefix(buf)
 317         if buf[4] == 0 then
 318                 printf("%s\tkevent requested a thread at %s\n", prefix, parse_pthread_priority(buf[3]));
 319         elseif buf[4] == 1 then
 320                 printf("%s\tworkloop requested a thread for req %x at %s\n", prefix, buf[2], parse_pthread_priority(buf[3]));
 321         elseif buf[4] == 2 then
 322                 printf("%s\tworkloop updated priority of req %x to %s\n", prefix, buf[2], parse_pthread_priority(buf[3]));
 323         elseif buf[4] == 3 then
 324                 printf("%s\tworkloop canceled req %x\n", prefix, buf[2], parse_pthread_priority(buf[3]));
 325         elseif buf[4] == 4 then
 326                 printf("%s\tworkloop redrove a thread request\n", prefix);
 327         end
 328 end)
 329
 330 trace_codename("wq_constrained_admission", function(buf)
 331         local prefix = get_prefix(buf)
 332         if buf[2] == 1 then
 333                 printf("fail: %s\twq_constrained_threads_scheduled=%d >= wq_max_constrained_threads=%d\n",
 334                 prefix, buf[3], buf[4])
 335         elseif (buf[2] == 2) or (buf[2] == 3) then
 336                 local success = nil;
 337                 if buf[2] == 2 then success = "success"
 338                 else success = "fail" end
 339                 printf("%s: %s\tthactive_count=%d + busycount=%d >= wq->wq_max_concurrency\n",
 340                                 prefix, success, buf[3], buf[4])
 341         end
 342 end)
 343
 344 -- The trace codes we need aren't enabled by default
 345 darwin.sysctlbyname("kern.pthread_debug_tracing", 1)
 346 completion_handler = function()
 347         darwin.sysctlbyname("kern.pthread_debug_tracing", 0)
 348 end
 349 trace.set_completion_handler(completion_handler)