tools/trace/kqtrace.lua

   1 #!/usr/local/bin/luatrace -s
   2
   3 trace_eventname = 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
  14 function event_prefix_string(buf, workq)
  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 type
  21         if trace.debugid_is_start(buf.debugid) then
  22                 type = "→"
  23         elseif trace.debugid_is_end(buf.debugid) then
  24                 type = "←"
  25         else
  26                 type = "↔"
  27         end
  28
  29         proc = buf.command
  30
  31         local prefix = string.format("%s %6.9f %-17s [%05d.%06x] %-28s\t",
  32                 type, secs, proc, buf.pid, buf.threadid, buf.debugname)
  33         if not workq then
  34                 prefix = prefix .. string.format(" 0x%16x", buf.arg1)
  35         end
  36
  37         return prefix
  38 end
  39
  40 function qos_string(qos)
  41         if qos == 0 then
  42                 return "--"
  43         elseif qos == 1 then
  44                 return "MT"
  45         elseif qos == 2 then
  46                 return "BG"
  47         elseif qos == 3 then
  48                 return "UT"
  49         elseif qos == 4 then
  50                 return "DF"
  51         elseif qos == 5 then
  52                 return "IN"
  53         elseif qos == 6 then
  54                 return "UI"
  55         elseif qos == 7 then
  56                 return "MG"
  57         else
  58                 return string.format("??[0x%x]", qos)
  59         end
  60 end
  61
  62 function state_string(strings, state)
  63         local str = ''
  64         local first = true
  65         for name, bit in pairs(strings) do
  66                 if (state & bit) == bit then
  67                         if not first then
  68                                 str = str .. ' '
  69                         end
  70                         str = str .. name
  71                         first = false
  72                 end
  73         end
  74         return str
  75 end
  76
  77 kqrequest_state_strings = {
  78         ['PROCESSING'] = 0x1,
  79         ['THREQUESTED'] = 0x2,
  80         ['WAKEUP'] = 0x4
  81 }
  82
  83 kqueue_state_strings = {
  84         ['SEL'] = 0x001,
  85         ['SLEEP'] = 0x002,
  86         ['PROCWAIT'] = 0x004,
  87         ['KEV32'] = 0x008,
  88         ['KEV64'] = 0x010,
  89         ['KEV_QOS'] = 0x020,
  90         ['WORKQ'] = 0x040,
  91         ['WORKLOOP'] = 0x080,
  92         ['PROCESSING'] = 0x100,
  93         ['DRAIN'] = 0x200,
  94         ['WAKEUP'] = 0x400,
  95         ['DYNAMIC'] = 0x800,
  96 }
  97
  98 knote_state_strings = {
  99         ['ACTIVE'] = 0x0001,
 100         ['QUEUED'] = 0x0002,
 101         ['DISABLED'] = 0x0004,
 102         ['DROPPING'] = 0x0008,
 103         ['USEWAIT'] = 0x0010,
 104         ['ATTACHING'] = 0x0020,
 105         ['STAYACTIVE'] = 0x0040,
 106         ['DEFERDELETE'] = 0x0080,
 107         ['ATTACHED'] = 0x0100,
 108         ['DISPATCH'] = 0x0200,
 109         ['UDATA_SPECIFIC'] = 0x0400,
 110         ['SUPPRESSED'] = 0x0800,
 111         ['STOLENDROP'] = 0x1000,
 112         ['REQVANISH'] = 0x2000,
 113         ['VANISHED'] = 0x4000,
 114 }
 115 knote_state_strings = {
 116         ['ACTIVE'] = 0x0001,
 117         ['QUEUED'] = 0x0002,
 118         ['DISABLED'] = 0x0004,
 119         ['DROPPING'] = 0x0008,
 120         ['USEWAIT'] = 0x0010,
 121         ['ATTACHING'] = 0x0020,
 122         ['STAYACTIVE'] = 0x0040,
 123         ['DEFERDELETE'] = 0x0080,
 124         ['ATTACHED'] = 0x0100,
 125         ['DISPATCH'] = 0x0200,
 126         ['UDATA_SPECIFIC'] = 0x0400,
 127         ['SUPPRESSED'] = 0x0800,
 128         ['STOLENDROP'] = 0x1000,
 129         ['REQVANISH'] = 0x2000,
 130         ['VANISHED'] = 0x4000,
 131 }
 132
 133
 134 kevent_flags_strings = {
 135         ['ADD'] = 0x0001,
 136         ['DELETE'] = 0x0002,
 137         ['ENABLE'] = 0x0004,
 138         ['DISABLE'] = 0x0008,
 139         ['ONESHOT'] = 0x0010,
 140         ['CLEAR'] = 0x0020,
 141         ['RECEIPT'] = 0x0040,
 142         ['DISPATCH'] = 0x0080,
 143         ['UDATA_SPECIFIC'] = 0x0100,
 144         ['VANISHED'] = 0x0200,
 145         ['FLAG0'] = 0x1000,
 146         ['FLAG1'] = 0x2000,
 147         ['EOF'] = 0x8000,
 148         ['ERROR'] = 0x4000,
 149 }
 150
 151 function kevent_filter_string(filt)
 152         if filt == -1 then
 153                 return 'READ'
 154         elseif filt == -2 then
 155                 return 'WRITE'
 156         elseif filt == -3 then
 157                 return 'AIO'
 158         elseif filt == -4 then
 159                 return 'VNODE'
 160         elseif filt == -5 then
 161                 return 'PROC'
 162         elseif filt == -6 then
 163                 return 'SIGNAL'
 164         elseif filt == -7 then
 165                 return 'TIMER'
 166         elseif filt == -8 then
 167                 return 'MACHPORT'
 168         elseif filt == -9 then
 169                 return 'FS'
 170         elseif filt == -10 then
 171                 return 'USER'
 172         -- -11 unused
 173         elseif filt == -12 then
 174                 return 'VM'
 175         elseif filt == -13 then
 176                 return 'SOCK'
 177         elseif filt == -14 then
 178                 return 'MEMORYSTATUS'
 179         elseif filt == 15 then
 180                 return 'KQREAD'
 181         elseif filt == 16 then
 182                 return 'PIPE_R'
 183         elseif filt == 17 then
 184                 return 'PIPE_W'
 185         elseif filt == 18 then
 186                 return 'PTSD'
 187         elseif filt == 19 then
 188                 return 'SOWRITE'
 189         elseif filt == 20 then
 190                 return 'SOEXCEPT'
 191         elseif filt == 21 then
 192                 return 'SPEC'
 193         elseif filt == 22 then
 194                 return 'BPFREAD'
 195         elseif filt == 23 then
 196                 return 'NECP_FD'
 197         elseif filt == 24 then
 198                 return 'SKYWALK_CHANNEL_W'
 199         elseif filt == 25 then
 200                 return 'SKYWALK_CHANNEL_R'
 201         elseif filt == 26 then
 202                 return 'FSEVENT'
 203         elseif filt == 27 then
 204                 return 'VN'
 205         elseif filt == 28 then
 206                 return 'SKYWALK_CHANNEL_E'
 207         elseif filt == 29 then
 208                 return 'TTY'
 209         else
 210                 return string.format('[%d]', filt)
 211         end
 212 end
 213
 214 -- kqueue lifecycle
 215
 216 function processing_begin(workq)
 217         return function(buf)
 218                 local prefix = event_prefix_string(buf, workq)
 219                 if trace.debugid_is_start(buf.debugid) then
 220                         local qos
 221                         if workq then
 222                                 qos = buf.arg2
 223                         else
 224                                 qos = buf.arg3
 225                         end
 226                         printf("%s QoS = %s\n", prefix, qos_string(qos))
 227                 else
 228                         printf("%s request thread = 0x%x, kqrequest state = %s\n", prefix,
 229                                         buf.arg1, state_string(kqrequest_state_strings, buf.arg2))
 230                 end
 231         end
 232 end
 233
 234 trace_eventname("KEVENT_kq_processing_begin", processing_begin(false))
 235 trace_eventname("KEVENT_kqwq_processing_begin", processing_begin(true))
 236 trace_eventname("KEVENT_kqwl_processing_begin", processing_begin(false))
 237
 238 function processing_end(workq)
 239         return function(buf)
 240                 local qos
 241                 if workq then
 242                         qos = buf.arg2
 243                 else
 244                         qos = buf.arg3
 245                 end
 246                 printf("%s QoS = %s\n", event_prefix_string(buf, workq), qos_string(qos))
 247         end
 248 end
 249
 250 trace_eventname("KEVENT_kq_processing_end", processing_end(false))
 251 trace_eventname("KEVENT_kqwq_processing_end", processing_end(true))
 252 trace_eventname("KEVENT_kqwl_processing_end", processing_end(false))
 253
 254 trace_eventname("KEVENT_kqwq_bind", function(buf)
 255         printf("%s thread = 0x%x, QoS = %s, kqrequest state = %s\n",
 256                         event_prefix_string(buf, true), buf.arg1, qos_string(buf.arg3),
 257                         state_string(kqrequest_state_strings, buf.arg4))
 258 end)
 259
 260 trace_eventname("KEVENT_kqwq_unbind", function(buf)
 261         printf("%s thread = 0x%x, QoS = %s\n", event_prefix_string(buf, true),
 262                         buf.arg1, qos_string(buf.arg3))
 263 end)
 264
 265 trace_eventname("KEVENT_kqwl_bind", function(buf)
 266         qos = buf.arg3 & 0xff
 267         duplicate = buf.arg3 & (1 << 8)
 268         kqr_override_qos_delta = buf.arg4 >> 8
 269         kqr_state = buf.arg4 & 0xff
 270
 271         printf("%s thread = 0x%x, QoS = %s, override QoS delta = %d, kqrequest state = %s%s\n",
 272                         event_prefix_string(buf, false), buf.arg2, qos_string(qos),
 273                         kqr_override_qos_delta,
 274                         state_string(kqrequest_state_strings, kqr_state),
 275                         duplicate ? ", duplicate" : "")
 276 end)
 277
 278 trace_eventname("KEVENT_kqwl_unbind", function(buf)
 279         flags = buf.arg3
 280         qos = buf.arg4
 281
 282         printf("%s thread = 0x%x, QoS = %s, flags = 0x%x\n", event_prefix_string(buf, false),
 283                         buf.arg2, qos_string(qos), flags)
 284 end)
 285
 286 function thread_request(workq)
 287         return function(buf)
 288                 printf("%s QoS = %s, kqrequest state = %s, override QoS delta = %d\n",
 289                                 event_prefix_string(buf, workq), qos_string(buf.arg2),
 290                                 state_string(kqrequest_state_strings, buf.arg3), buf.arg3 >> 8)
 291         end
 292 end
 293
 294 function thread_adjust(buf)
 295         tid = buf.arg2
 296         kqr_qos = buf.arg3 >> 8
 297         new_qos = buf.arg3 & 0xff
 298         kqr_qos_override = buf.arg4 >> 8
 299         kqr_state = buf.arg4 & 0xff
 300
 301         printf("%s thread = 0x%x, old/new QoS = %s/%s, old/new override QoS delta = %d/%d, kqrequest state = %s\n",
 302                         event_prefix_string(buf, false),
 303                         tid,
 304                         qos_string(kqr_qos),
 305                         qos_string(new_qos),
 306                         kqr_qos_override,
 307                         new_qos - kqr_qos,
 308                         state_string(kqrequest_state_strings, kqr_state))
 309 end
 310
 311 trace_eventname("KEVENT_kqwq_thread_request", thread_request(true))
 312 trace_eventname("KEVENT_kqwl_thread_request", thread_request(false))
 313 trace_eventname("KEVENT_kqwl_thread_adjust", thread_adjust)
 314
 315 function kevent_register(workq)
 316         return function(buf)
 317                 printf("%s kevent udata = 0x%x, kevent filter = %s, kevent flags = %s\n",
 318                                 event_prefix_string(buf, workq), buf.arg2,
 319                                 kevent_filter_string(buf.arg4),
 320                                 state_string(kevent_flags_strings, buf.arg3))
 321         end
 322 end
 323
 324 trace_eventname("KEVENT_kq_register", kevent_register(false))
 325 trace_eventname("KEVENT_kqwq_register", kevent_register(true))
 326 trace_eventname("KEVENT_kqwl_register", kevent_register(false))
 327
 328 function kevent_process(workq)
 329         return function(buf)
 330                 printf("%s kevent ident = 0x%x, udata = 0x%x, kevent filter = %s, knote status = %s\n",
 331                                 event_prefix_string(buf, workq), buf.arg3 >> 32, buf.arg2,
 332                                 kevent_filter_string(buf.arg4),
 333                                 state_string(knote_state_strings, buf.arg3 & 0xffffffff))
 334         end
 335 end
 336
 337 trace_eventname("KEVENT_kq_process", kevent_process(false))
 338 trace_eventname("KEVENT_kqwq_process", kevent_process(true))
 339 trace_eventname("KEVENT_kqwl_process", kevent_process(false))