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