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] %-24s",
  32                 prefix, secs, proc, buf.pid, buf.threadid, buf.debugname)
  33 end
  34
  35 decode_lval = function(lval)
  36         local kbit = " "
  37         if lval & 0x1 ~= 0 then
  38                 kbit = "K"
  39         end
  40         local ebit = " "
  41         if lval & 0x2 ~= 0 then
  42                 ebit = "E"
  43         end
  44         local wbit = " "
  45         if lval & 0x4 ~= 0 then
  46                 wbit = "W"
  47         end
  48
  49         local count = lval >> 8
  50         return string.format("[0x%06x, %s%s%s]", count, wbit, ebit, kbit)
  51 end
  52
  53 decode_sval = function(sval)
  54         local sbit = " "
  55         if sval & 0x1 ~= 0 then
  56                 sbit = "S"
  57         end
  58         local ibit = " "
  59         if sval & 0x2 ~= 0 then
  60                 ibit = "I"
  61         end
  62
  63         local count = sval >> 8
  64         return string.format("[0x%06x, %s%s]", count, ibit, sbit)
  65 end
  66
  67 trace_codename("psynch_mutex_lock_updatebits", function(buf)
  68         local prefix = get_prefix(buf)
  69         if buf[4] == 0 then
  70                 printf("%s\tupdated lock bits, pre-kernel (addr: 0x%016x, oldlval: %s, newlval: %s)\n", prefix, buf[1], decode_lval(buf[2]), decode_lval(buf[3]))
  71         else
  72                 printf("%s\tupdated lock bits, post-kernel (addr: 0x%016x, oldlval: %s, newlval: %s)\n", prefix, buf[1], decode_lval(buf[2]), decode_lval(buf[3]))
  73         end
  74 end)
  75
  76 trace_codename("psynch_mutex_unlock_updatebits", function(buf)
  77         local prefix = get_prefix(buf)
  78         printf("%s\tupdated unlock bits (addr: 0x%016x, oldlval: %s, newlval: %s)\n", prefix, buf[1], decode_lval(buf[2]), decode_lval(buf[3]))
  79 end)
  80
  81 trace_codename("psynch_mutex_ulock", function(buf)
  82         local prefix = get_prefix(buf)
  83
  84         if trace.debugid_is_start(buf.debugid) then
  85                 printf("%s\tlock busy, waiting in kernel (addr: 0x%016x, lval: %s, sval: %s, owner_tid: 0x%x)\n",
  86                         prefix, buf[1], decode_lval(buf[2]), decode_sval(buf[3]), buf[4])
  87         elseif trace.debugid_is_end(buf.debugid) then
  88                 printf("%s\tlock acquired from kernel (addr: 0x%016x, updated bits: %s)\n",
  89                         prefix, buf[1], decode_lval(buf[2]))
  90         else
  91                 printf("%s\tlock taken, uncontended (addr: 0x%016x, lval: %s, sval: %s)\n",
  92                         prefix, buf[1], decode_lval(buf[2]), decode_sval(buf[3]))
  93         end
  94 end)
  95
  96 trace_codename("psynch_mutex_utrylock_failed", function(buf)
  97         local prefix = get_prefix(buf)
  98         printf("%s\tmutex trybusy addr: 0x%016x lval: %s sval: %s owner: 0x%x\n", prefix, buf[1], decode_lval(buf[2]), decode_sval(buf[3]), buf[4])
  99 end)
 100
 101 trace_codename("psynch_mutex_uunlock", function(buf)
 102         local prefix = get_prefix(buf)
 103
 104         if trace.debugid_is_start(buf.debugid) then
 105                 printf("%s\tunlock, signalling kernel waiters (addr: 0x%016x, lval: %s, sval: %s, owner_tid: 0x%x)\n",
 106                         prefix, buf[1], decode_lval(buf[2]), decode_sval(buf[3]), buf[4])
 107         elseif trace.debugid_is_end(buf.debugid) then
 108                 printf("%s\tunlock, waiters signalled (addr: 0x%016x, updated bits: %s)\n",
 109                         prefix, buf[1], decode_lval(buf[2]))
 110         else
 111                 printf("%s\tunlock, no kernel waiters (addr: 0x%016x, lval: %s, sval: %s)\n",
 112                         prefix, buf[1], decode_lval(buf[2]), decode_sval(buf[3]))
 113         end
 114 end)
 115
 116 -- The trace codes we need aren't enabled by default
 117 darwin.sysctlbyname("kern.pthread_debug_tracing", 1)
 118 completion_handler = function()
 119         darwin.sysctlbyname("kern.pthread_debug_tracing", 0)
 120 end
 121 trace.set_completion_handler(completion_handler)