tools/locktrace.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 get_prefix = function(buf)
  14         if initial_timestamp == 0 then
  15                 initial_timestamp = buf.timestamp
  16         end
  17         local secs = trace.convert_timestamp_to_nanoseconds(buf.timestamp - initial_timestamp) / 1000000000
  18
  19         local prefix
  20         if trace.debugid_is_start(buf.debugid) then
  21                 prefix = "→"
  22         elseif trace.debugid_is_end(buf.debugid) then
  23                 prefix = "←"
  24         else
  25                 prefix = "↔"
  26         end
  27
  28         local proc
  29         proc = buf.command
  30
  31         return string.format("%s %6.9f %-17s [%05d.%06x] %-35s",
  32                 prefix, secs, proc, buf.pid, buf.threadid, buf.debugname)
  33 end
  34
  35 get_count = function(val)
  36         return ((val & 0xffffff00) >> 8)
  37 end
  38
  39 get_kwq_type = function(val)
  40         if val & 0xff == 0x1 then
  41                 return "MTX"
  42         elseif val & 0xff == 0x2 then
  43                 return "CVAR"
  44         elseif val & 0xff == 0x4 then
  45                 return "RWL"
  46         else
  47                 return string.format("0x%04x", val)
  48         end
  49 end
  50
  51 decode_lval = function(lval)
  52         local kbit = " "
  53         if lval & 0x1 ~= 0 then
  54                 kbit = "K"
  55         end
  56         local ebit = " "
  57         if lval & 0x2 ~= 0 then
  58                 ebit = "E"
  59         end
  60         local wbit = " "
  61         if lval & 0x4 ~= 0 then
  62                 wbit = "W"
  63         end
  64
  65         local count = lval >> 8
  66         return string.format("[0x%06x, %s%s%s]", count, wbit, ebit, kbit)
  67 end
  68
  69 decode_sval = function(sval)
  70         local sbit = " "
  71         if sval & 0x1 ~= 0 then
  72                 sbit = "S"
  73         end
  74         local ibit = " "
  75         if sval & 0x2 ~= 0 then
  76                 ibit = "I"
  77         end
  78
  79         local count = sval >> 8
  80         return string.format("[0x%06x,  %s%s]", count, ibit, sbit)
  81 end
  82
  83 decode_cv_sval = function(sval)
  84         local sbit = " "
  85         if sval & 0x1 ~= 0 then
  86                 sbit = "C"
  87         end
  88         local ibit = " "
  89         if sval & 0x2 ~= 0 then
  90                 ibit = "P"
  91         end
  92
  93         local count = sval >> 8
  94         return string.format("[0x%06x,  %s%s]", count, ibit, sbit)
  95 end
  96
  97 trace_codename("psynch_mutex_lock_updatebits", function(buf)
  98         local prefix = get_prefix(buf)
  99         if buf[4] == 0 then
 100                 printf("%s\tupdated lock bits, pre-kernel\taddr: 0x%016x\toldl: %s\tnewl: %s\n",
 101                                 prefix, buf[1], decode_lval(buf[2]), decode_lval(buf[3]))
 102         else
 103                 printf("%s\tupdated lock bits, post-kernel\taddr: 0x%016x\toldl: %s\tnewl: %s\n",
 104                                 prefix, buf[1], decode_lval(buf[2]), decode_lval(buf[3]))
 105         end
 106 end)
 107
 108 trace_codename("psynch_mutex_unlock_updatebits", function(buf)
 109         local prefix = get_prefix(buf)
 110         printf("%s\tupdated unlock bits\t\taddr: 0x%016x\toldl: %s\tnewl: %s\n",
 111                         prefix, buf[1], decode_lval(buf[2]), decode_lval(buf[3]))
 112 end)
 113
 114 trace_codename("psynch_ffmutex_lock_updatebits", function(buf)
 115         local prefix = get_prefix(buf)
 116         if trace.debugid_is_start(buf.debugid) then
 117                 printf("%s\tlock path, bits update\t\taddr: 0x%016x\toldl: %s\toldu: %s\twaiters: %d\n",
 118                                 prefix, buf[1], decode_lval(buf[2]), decode_sval(buf[3]), get_count(buf[2]) - get_count(buf[3]))
 119         else
 120                 printf("%s\tlock path, bits update\t\taddr: 0x%016x\tnewl: %s\tnewu: %s\twaiters: %d\n",
 121                                 prefix, buf[1], decode_lval(buf[2]), decode_sval(buf[3]), get_count(buf[2]) - get_count(buf[3]))
 122         end
 123 end)
 124
 125 trace_codename("psynch_ffmutex_unlock_updatebits", function(buf)
 126         local prefix = get_prefix(buf)
 127         printf("%s\tunlock path, update bits\taddr: 0x%016x\toldl: %s\tnewl: %s\tnewu: %s\n",
 128                         prefix, buf[1], decode_lval(buf[2]), decode_lval(buf[3]), decode_sval(buf[4]))
 129 end)
 130
 131 trace_codename("psynch_ffmutex_wake", function(buf)
 132         local prefix = get_prefix(buf)
 133         printf("%s\tfirst fit kernel wake\t\taddr: 0x%016x\tlval: %s\tuval: %s\n",
 134                         prefix, buf[1], decode_lval(buf[2]), decode_sval(buf[3]))
 135 end)
 136
 137 trace_codename("psynch_ffmutex_wait", function(buf)
 138         local prefix = get_prefix(buf)
 139         if trace.debugid_is_start(buf.debugid) then
 140                 printf("%s\tfirstfit kernel wait\t\taddr: 0x%016x\tlval: %s\tuval: %s\tflags: 0x%x\n",
 141                         prefix, buf[1], decode_lval(buf[2]), decode_sval(buf[3]), buf[4])
 142         else
 143                 printf("%s\tfirstfit kernel wait\t\taddr: 0x%016x\trval: %s\n",
 144                         prefix, buf[1], decode_lval(buf[2]))
 145         end
 146 end)
 147
 148 trace_codename("psynch_mutex_ulock", function(buf)
 149         local prefix = get_prefix(buf)
 150
 151         if trace.debugid_is_start(buf.debugid) then
 152                 printf("%s\tlock busy, waiting in kernel\taddr: 0x%016x\tlval: %s\tsval: %s\towner_tid: 0x%x\n",
 153                         prefix, buf[1], decode_lval(buf[2]), decode_sval(buf[3]), buf[4])
 154         elseif trace.debugid_is_end(buf.debugid) then
 155                 printf("%s\tlock acquired from kernel\taddr: 0x%016x\tupdt: %s\n",
 156                         prefix, buf[1], decode_lval(buf[2]))
 157         else
 158                 printf("%s\tlock taken userspace\t\taddr: 0x%016x\tlval: %s\tsval: %s\n",
 159                         prefix, buf[1], decode_lval(buf[2]), decode_sval(buf[3]))
 160         end
 161 end)
 162
 163 trace_codename("psynch_mutex_utrylock_failed", function(buf)
 164         local prefix = get_prefix(buf)
 165         printf("%s\tmutex trybusy\t\t\taddr: 0x%016x\tlval: %s\tsval: %s\towner: 0x%x\n", prefix, buf[1], decode_lval(buf[2]), decode_sval(buf[3]), buf[4])
 166 end)
 167
 168 trace_codename("psynch_mutex_uunlock", function(buf)
 169         local prefix = get_prefix(buf)
 170
 171         if trace.debugid_is_start(buf.debugid) then
 172                 printf("%s\tunlock, signalling kernel\taddr: 0x%016x\tlval: %s\tsval: %s\towner_tid: 0x%x\n",
 173                         prefix, buf[1], decode_lval(buf[2]), decode_sval(buf[3]), buf[4])
 174         elseif trace.debugid_is_end(buf.debugid) then
 175                 printf("%s\tunlock, waiters signalled\taddr: 0x%016x\tupdt: %s\n",
 176                         prefix, buf[1], decode_lval(buf[2]))
 177         else
 178                 printf("%s\tunlock, no kernel waiters\taddr: 0x%016x\tlval: %s\tsval: %s\n",
 179                         prefix, buf[1], decode_lval(buf[2]), decode_sval(buf[3]))
 180         end
 181 end)
 182
 183 trace_codename("psynch_mutex_clearprepost", function(buf)
 184         local prefix = get_prefix(buf)
 185         printf("%s\tclear prepost\t\t\taddr: 0x%016x\tlval: %s\tsval: %s\n",
 186                 prefix, buf[1], decode_lval(buf[2]), decode_sval(buf[3]))
 187 end)
 188
 189 trace_codename("psynch_mutex_markprepost", function(buf)
 190         local prefix = get_prefix(buf)
 191         if trace.debugid_is_start(buf.debugid) then
 192                 printf("%s\tmark prepost\t\t\taddr: 0x%016x\tlval: %s\tsval: %s\n",
 193                         prefix, buf[1], decode_lval(buf[2]), decode_sval(buf[3]))
 194         else
 195                 printf("%s\tmark prepost\t\t\taddr: 0x%016x\tcleared: %d\n",
 196                         prefix, buf[1], buf[2])
 197         end
 198 end)
 199
 200 trace_codename("psynch_mutex_kwqallocate", function(buf)
 201         local prefix = get_prefix(buf)
 202         if trace.debugid_is_start(buf.debugid) then
 203                 printf("%s\tkernel kwq allocated\t\taddr: 0x%016x\ttype: %s\tkwq: 0x%016x\n",
 204                         prefix, buf[1], get_kwq_type(buf[2]), buf[3])
 205         elseif trace.debugid_is_end(buf.debugid) then
 206                 printf("%s\tkernel kwq allocated\t\taddr: 0x%016x\tlval: %s\tuval: %s\tsval: %s\n",
 207                         prefix, buf[1], decode_lval(buf[2]), decode_lval(buf[3]), decode_sval(buf[4]))
 208         end
 209 end)
 210
 211 trace_codename("psynch_mutex_kwqdeallocate", function(buf)
 212         local prefix = get_prefix(buf)
 213         if trace.debugid_is_start(buf.debugid) then
 214                 printf("%s\tkernel kwq deallocated\t\taddr: 0x%016x\ttype: %s\tfreenow: %d\n",
 215                         prefix, buf[1], get_kwq_type(buf[2]), buf[3])
 216         elseif trace.debugid_is_end(buf.debugid) then
 217                 printf("%s\tkernel kwq deallocated\t\taddr: 0x%016x\tlval: %s\tuval: %s\tsval: %s\n",
 218                         prefix, buf[1], decode_lval(buf[2]), decode_lval(buf[3]), decode_sval(buf[4]))
 219         end
 220 end)
 221
 222 trace_codename("psynch_mutex_kwqprepost", function(buf)
 223         local prefix = get_prefix(buf)
 224         if buf[4] == 0 then
 225                 printf("%s\tkernel prepost incremented\taddr: 0x%016x\tlval: %s\tinqueue: %d\n",
 226                         prefix, buf[1], decode_lval(buf[2]), buf[3])
 227         elseif buf[4] == 1 then
 228                 printf("%s\tkernel prepost decremented\taddr: 0x%016x\tlval: %s\tremaining: %d\n",
 229                         prefix, buf[1], decode_lval(buf[2]), buf[3])
 230         elseif buf[4] == 2 then
 231                 printf("%s\tkernel prepost cleared\t\taddr: 0x%016x\tlval: %s\n", prefix,
 232                         buf[1], decode_lval(buf[2]))
 233         end
 234 end)
 235
 236 trace_codename("psynch_mutex_kwqcollision", function(buf)
 237         local prefix = get_prefix(buf)
 238         printf("%s\tkernel kwq collision\t\taddr: 0x%016x\ttype: %d\n", prefix,
 239                 buf[1], buf[2])
 240 end)
 241
 242 trace_codename("psynch_mutex_kwqsignal", function(buf)
 243         local prefix = get_prefix(buf)
 244         if trace.debugid_is_start(buf.debugid) then
 245                 printf("%s\tkernel mutex signal\t\taddr: 0x%016x\tkwe: 0x%16x\ttid: 0x%x\tinqueue: %d\n",
 246                         prefix, buf[1], buf[2], buf[3], buf[4]);
 247         else
 248                 printf("%s\tkernel mutex signal\t\taddr: 0x%016x\tkwe: 0x%16x\tret: 0x%x\n",
 249                         prefix, buf[1], buf[2], buf[3]);
 250         end
 251 end)
 252
 253 trace_codename("psynch_mutex_kwqwait", function(buf)
 254         local prefix = get_prefix(buf)
 255         printf("%s\tkernel mutex wait\t\taddr: 0x%016x\tinqueue: %d\tprepost: %d\tintr: %d\n",
 256                 prefix, buf[1], buf[2], buf[3], buf[4])
 257 end)
 258
 259 trace_codename("psynch_cvar_kwait", function(buf)
 260         local prefix = get_prefix(buf)
 261         if buf[4] == 0 then
 262                 printf("%s\tkernel condvar wait\t\taddr: 0x%016x\tmutex: 0x%016x\tcgen: 0x%x\n",
 263                         prefix, buf[1], buf[2], buf[3])
 264         elseif buf[4] == 1 then
 265                 printf("%s\tkernel condvar sleep\t\taddr: 0x%016x\tflags: 0x%x\n",
 266                         prefix, buf[1], buf[3])
 267         elseif buf[4] == 2 then
 268                 printf("%s\tkernel condvar wait return\taddr: 0x%016x\terror: 0x%x\tupdt: 0x%x\n",
 269                         prefix, buf[1], buf[2], buf[3])
 270         elseif buf[4] == 3 and (buf[2] & 0xff) == 60 then
 271                 printf("%s\tkernel condvar timeout\t\taddr: 0x%016x\terror: 0x%x\n",
 272                         prefix, buf[1], buf[2])
 273         elseif buf[4] == 3 then
 274                 printf("%s\tkernel condvar wait error\taddr: 0x%016x\terror: 0x%x\n",
 275                         prefix, buf[1], buf[2])
 276         elseif buf[4] == 4 then
 277                 printf("%s\tkernel condvar wait return\taddr: 0x%016x\tupdt: 0x%x\n",
 278                         prefix, buf[1], buf[2])
 279         end
 280 end)
 281
 282 trace_codename("psynch_cvar_clrprepost", function(buf)
 283         local prefix = get_prefix(buf)
 284         printf("%s\tkernel condvar clear prepost:\taddr: 0x%016x\ttype: 0x%x\tprepost seq: %s\n",
 285                 prefix, buf[1], buf[2], decode_lval(buf[3]))
 286 end)
 287
 288 trace_codename("psynch_cvar_freeitems", function(buf)
 289         local prefix = get_prefix(buf)
 290         if trace.debugid_is_start(buf.debugid) then
 291                 printf("%s\tcvar free fake/prepost items\taddr: 0x%016x\ttype: %d\t\t\tupto: %s\tall: %d\n",
 292                         prefix, buf[1], buf[2], decode_lval(buf[3]), buf[4])
 293         elseif trace.debugid_is_end(buf.debugid) then
 294                 printf("%s\tcvar free fake/prepost items\taddr: 0x%016x\tfreed: %d\tsignaled: %d\tinqueue: %d\n",
 295                         prefix, buf[1], buf[2], buf[3], buf[4])
 296         elseif buf[4] == 1 then
 297                 printf("%s\tcvar free, signalling waiter\taddr: 0x%016x\tinqueue: %d\tkwe: 0x%016x\n",
 298                         prefix, buf[1], buf[3], buf[2])
 299         elseif buf[4] == 2 then
 300                 printf("%s\tcvar free, removing fake\taddr: 0x%016x\tinqueue: %d\tkwe: 0x%016x\n",
 301                         prefix, buf[1], buf[3], buf[2])
 302         end
 303 end)
 304
 305 trace_codename("psynch_cvar_signal", function(buf)
 306         local prefix = get_prefix(buf)
 307         if trace.debugid_is_start(buf.debugid) then
 308                 printf("%s\tkernel cvar signal\t\taddr: 0x%016x\tfrom: %s\tupto: %s\tbroad: %d\n",
 309                         prefix, buf[1], decode_lval(buf[2]), decode_lval(buf[3]), buf[4])
 310         elseif trace.debugid_is_end(buf.debugid) then
 311                 printf("%s\tkernel cvar signal\t\taddr: 0x%016x\tupdt: %s\n",
 312                         prefix, buf[1], decode_cv_sval(buf[2]))
 313         else
 314                 printf("%s\tkernel cvar signal\t\taddr: 0x%016x\tsignalled waiters (converted to broadcast: %d)\n",
 315                         prefix, buf[1], buf[2])
 316         end
 317 end)
 318
 319 trace_codename("psynch_cvar_broadcast", function(buf)
 320         local prefix = get_prefix(buf)
 321         if trace.debugid_is_start(buf.debugid) then
 322                 printf("%s\tkernel cvar broadcast\t\taddr: 0x%016x\tupto: %s\tinqueue: %d\n",
 323                         prefix, buf[1], decode_lval(buf[2]), buf[3])
 324         elseif trace.debugid_is_end(buf.debugid) then
 325                 printf("%s\tkernel cvar broadcast\t\taddr: 0x%016x\tupdt: %s\n",
 326                         prefix, buf[1], decode_lval(buf[2]))
 327         elseif buf[4] == 1 then
 328                 printf("%s\tkernel cvar broadcast\t\taddr: 0x%016x\tsignalling: 0x%16x\n",
 329                         prefix, buf[1], buf[2])
 330         elseif buf[4] == 2 then
 331                 printf("%s\tkernel cvar broadcast\t\taddr: 0x%016x\tremoving fake: 0x%16x\tstate: %d\n",
 332                         prefix, buf[1], buf[2], buf[3])
 333         elseif buf[4] == 3 then
 334                 printf("%s\tkernel cvar broadcast\t\taddr: 0x%016x\tprepost\tlval: %s\tsval: %s\n",
 335                         prefix, buf[1], decode_lval(buf[2]), decode_cv_sval(buf[3]))
 336         elseif buf[4] == 4 then
 337                 printf("%s\tkernel cvar broadcast\t\taddr: 0x%016x\tbroadcast prepost: 0x%016x\n",
 338                         prefix, buf[1], buf[2])
 339         end
 340 end)
 341
 342 trace_codename("psynch_cvar_zeroed", function(buf)
 343         local prefix = get_prefix(buf)
 344         printf("%s\tkernel cvar zeroed\t\taddr: 0x%016x\tlval: %s\tsval: %s\tinqueue: %d\n",
 345                 prefix, buf[1], decode_lval(buf[2]), decode_cv_sval(buf[3]), buf[4])
 346 end)
 347
 348 trace_codename("psynch_cvar_updateval", function(buf)
 349         local prefix = get_prefix(buf)
 350         if trace.debugid_is_start(buf.debugid) then
 351                 printf("%s\tcvar updateval\t\t\taddr: 0x%016x\tlval: %s\tsval: %s\tupdateval: %s\n",
 352                         prefix, buf[1], decode_lval(buf[2] & 0xffffffff), decode_cv_sval(buf[2] >> 32), decode_cv_sval(buf[3]))
 353         elseif trace.debugid_is_end(buf.debugid) then
 354                 printf("%s\tcvar updateval (updated)\taddr: 0x%016x\tlval: %s\tsval: %s\tdiffgen: %d\tneedsclear: %d\n",
 355                         prefix, buf[1], decode_lval(buf[2] & 0xffffffff), decode_cv_sval(buf[2] >> 32), buf[3] >> 32, buf[3] & 0x1)
 356         end
 357 end)
 358