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