tools/lldbmacros/ktrace.py

   1 from xnu import *
   2 from utils import *
   3 from core.lazytarget import *
   4 from misc import *
   5 from collections import namedtuple
   6
   7 # From the defines in bsd/sys/kdebug.h:
   8
   9 KdebugClassNames = {
  10     1: "MACH",
  11     2: "NETWORK",
  12     3: "FSYSTEM",
  13     4: "BSD",
  14     5: "IOKIT",
  15     6: "DRIVERS",
  16     7: "TRACE",
  17     8: "DLIL",
  18     9: "WORKQUEUE",
  19     10: "CORESTORAGE",
  20     11: "CG",
  21     20: "MISC",
  22     30: "SECURITY",
  23     31: "DYLD",
  24     32: "QT",
  25     33: "APPS",
  26     34: "LAUNCHD",
  27     36: "PPT",
  28     37: "PERF",
  29     38: "IMPORTANCE",
  30     39: "PERFCTRL",
  31     40: "BANK",
  32     41: "XPC",
  33     42: "ATM",
  34     43: "ARIADNE",
  35     44: "DAEMON",
  36     45: "ENERGYTRACE",
  37     49: "IMG",
  38     50: "CLPC",
  39     128: "ANS",
  40     129: "SIO",
  41     130: "SEP",
  42     131: "ISP",
  43     132: "OSCAR",
  44     133: "EMBEDDEDGFX"
  45 }
  46
  47 def GetKdebugClassName(class_num):
  48     return (KdebugClassNames[class_num] + ' ({})'.format(class_num) if class_num in KdebugClassNames else 'unknown ({})'.format(class_num))
  49
  50 @lldb_type_summary(['typefilter_t'])
  51 @header('{0: <20s}'.format("class") + ' '.join(map('{:02x}'.format, xrange(0, 255, 8))))
  52 def GetKdebugTypefilter(typefilter):
  53     """ Summarizes the provided typefilter.
  54     """
  55     classes = 256
  56     subclasses_per_class = 256
  57
  58     # 8 bits at a time
  59     subclasses_per_element = 64
  60     cur_typefilter = cast(typefilter, 'uint64_t *')
  61     subclasses_fmts = ' '.join(['{:02x}'] * 8)
  62
  63     elements_per_class = subclasses_per_class / subclasses_per_element
  64
  65     out_str = ''
  66     for i in xrange(0, classes):
  67         print_class = False
  68         subclasses = [0] * elements_per_class
  69
  70         # check subclass ranges for set bits, remember those subclasses
  71         for j in xrange(0, elements_per_class):
  72             element = unsigned(cur_typefilter[i * elements_per_class + j])
  73             if element != 0:
  74                 print_class = True
  75             if print_class:
  76                 subclasses[j] = element
  77
  78         ## if any of the bits were set in a class, print the entire class
  79         if print_class:
  80             out_str += '{:<20s}'.format(GetKdebugClassName(i))
  81             for element in subclasses:
  82                 # split up the 64-bit values into byte-sized pieces
  83                 bytes = [unsigned((element >> i) & 0xff) for i in (0, 8, 16, 24, 32, 40, 48, 56)]
  84                 out_str += subclasses_fmts.format(*bytes)
  85                 out_str += ' '
  86
  87             out_str += '\n'
  88
  89     return out_str
  90
  91 @lldb_command('showkdebugtypefilter')
  92 def ShowKdebugTypefilter(cmd_args=None):
  93     """ Show the current kdebug typefilter (or the typefilter at an address)
  94
  95         usage: showkdebugtypefilter [<address>]
  96     """
  97
  98     if cmd_args:
  99         typefilter = kern.GetValueFromAddress(cmd_args[0], 'typefilter_t')
 100         if unsigned(typefilter) == 0:
 101             raise ArgumentError('argument provided is NULL')
 102
 103         print GetKdebugTypefilter.header
 104         print '-' * len(GetKdebugTypefilter.header)
 105
 106         print GetKdebugTypefilter(typefilter)
 107         return
 108
 109     typefilter = kern.globals.kdbg_typefilter
 110     if unsigned(typefilter) == 0:
 111         raise ArgumentError('no argument provided and active typefilter is not set')
 112
 113     print GetKdebugTypefilter.header
 114     print '-' * len(GetKdebugTypefilter.header)
 115     print GetKdebugTypefilter(typefilter)
 116
 117 def GetKdebugStatus():
 118     """ Get a string summary of the kdebug subsystem.
 119     """
 120     out = ''
 121
 122     kdebug_flags = kern.globals.kd_ctrl_page.kdebug_flags
 123     out += 'kdebug flags: {}\n'.format(xnudefines.GetStateString(xnudefines.kdebug_flags_strings, kdebug_flags))
 124     events = kern.globals.nkdbufs
 125     buf_mb = events * (64 if kern.arch == 'x86_64' or kern.arch.startswith('arm64') else 32) / 1000000
 126     out += 'events allocated: {:<d} ({:<d} MB)\n'.format(events, buf_mb)
 127     out += 'enabled: {}\n'.format('yes' if kern.globals.kdebug_enable != 0 else 'no')
 128     if kdebug_flags & xnudefines.kdebug_typefilter_check:
 129         out += 'typefilter:\n'
 130         out += GetKdebugTypefilter.header + '\n'
 131         out += '-' * len(GetKdebugTypefilter.header) + '\n'
 132         typefilter = kern.globals.kdbg_typefilter
 133         if unsigned(typefilter) != 0:
 134             out += GetKdebugTypefilter(typefilter)
 135
 136     return out
 137
 138 @lldb_command('showkdebug')
 139 def ShowKdebug(cmd_args=None):
 140     """ Show the current kdebug state.
 141
 142         usage: showkdebug
 143     """
 144
 145     print GetKdebugStatus()
 146
 147 @lldb_type_summary(['kperf_timer'])
 148 @header('{:<10s} {:<7s} {:<20s} {:<20s}'.format('period-ns', 'action', 'deadline', 'fire-time'))
 149 def GetKperfTimerSummary(timer):
 150     """ Get a string summary of a kperf timer.
 151
 152         params:
 153             timer: the kptimer object to get a summary of
 154     """
 155     try:
 156         fire_time = timer.kt_fire_time
 157     except:
 158         fire_time = 0
 159     return '{:<10d} {:<7d} {:<20d} {:<20d}\n'.format(
 160         kern.GetNanotimeFromAbstime(timer.kt_period_abs), timer.kt_actionid,
 161         timer.kt_cur_deadline, fire_time)
 162
 163 @lldb_type_summary(['action'])
 164 @header('{:<10s} {:<20s} {:<20s}'.format('pid-filter', 'user-data', 'samplers'))
 165 def GetKperfActionSummary(action):
 166     """ Get a string summary of a kperf action.
 167
 168         params:
 169             action: the action object to get a summary of
 170     """
 171     samplers = xnudefines.GetStateString(xnudefines.kperf_samplers_strings, action.sample)
 172     return '{:<10s} {:<20x} {:<20s}\n'.format(
 173         '-' if action.pid_filter < 0 else str(action.pid_filter), action.userdata, samplers)
 174
 175 def GetKperfStatus():
 176     """ Get a string summary of the kperf subsystem.
 177     """
 178     out = ''
 179
 180     kperf_status = int(kern.globals.kperf_status)
 181     out += 'sampling: '
 182     if kperf_status == GetEnumValue('kperf_sampling::KPERF_SAMPLING_OFF'):
 183         out += 'off\n'
 184     elif kperf_status == GetEnumValue('kperf_sampling::KPERF_SAMPLING_SHUTDOWN'):
 185         out += 'shutting down\n'
 186     elif kperf_status == GetEnumValue('kperf_sampling::KPERF_SAMPLING_ON'):
 187         out += 'on\n'
 188     else:
 189         out += 'unknown\n'
 190
 191     pet = kern.globals.kptimer.g_pet_active
 192     pet_timer_id = kern.globals.kptimer.g_pet_active
 193     if pet != 0:
 194         pet_idle_rate = kern.globals.pet_idle_rate
 195         out += 'legacy PET is active (timer = {:<d}, idle rate = {:<d})\n'.format(pet_timer_id, pet_idle_rate)
 196     else:
 197         out += 'legacy PET is off\n'
 198
 199     lw_pet = kern.globals.kppet.g_lightweight
 200     if lw_pet != 0:
 201         lw_pet_gen = kern.globals.kppet_gencount
 202         out += 'lightweight PET is active (timer = {:<d}, generation count = {:<d})\n'.format(pet_timer_id, lw_pet_gen)
 203     else:
 204         out += 'lightweight PET is off\n'
 205
 206     actions = kern.globals.actionc
 207     actions_arr = kern.globals.actionv
 208
 209     out += 'actions:\n'
 210     out += '{:<5s} '.format('id') + GetKperfActionSummary.header + '\n'
 211     for i in xrange(0, actions):
 212         out += '{:<5d} '.format(i) + GetKperfActionSummary(actions_arr[i])
 213
 214     timers = kern.globals.kptimer.g_ntimers
 215     timers_arr = kern.globals.kptimer.g_timers
 216
 217     out += 'timers:\n'
 218     out += '{:<5s} '.format('id') + GetKperfTimerSummary.header + '\n'
 219     for i in xrange(0, timers):
 220         out += '{:<5d} '.format(i) + GetKperfTimerSummary(timers_arr[i])
 221
 222     return out
 223
 224
 225 def GetKtraceStatus():
 226     """ Get a string summary of the ktrace subsystem.
 227     """
 228     out = ''
 229
 230     state = kern.globals.ktrace_state
 231     if state == GetEnumValue('ktrace_state::KTRACE_STATE_OFF'):
 232         out += 'ktrace is off\n'
 233     else:
 234         out += 'ktrace is active ('
 235         if state == GetEnumValue('ktrace_state::KTRACE_STATE_FG'):
 236             out += 'foreground)'
 237         else:
 238             out += 'background)'
 239         out += '\n'
 240         owner = kern.globals.ktrace_last_owner_execname
 241         out += 'owned by: {0: <s}\n'.format(owner)
 242         active_mask = kern.globals.ktrace_active_mask
 243         out += 'active systems: {:<#x}\n'.format(active_mask)
 244
 245     return out
 246
 247
 248 @lldb_command('showktrace')
 249 def ShowKtrace(cmd_args=None):
 250     """ Show the current ktrace state, including subsystems.
 251
 252         usage: showktrace
 253     """
 254
 255     print GetKtraceStatus()
 256     print ' '
 257     print 'kdebug:'
 258     print GetKdebugStatus()
 259     print ' '
 260     print 'kperf:'
 261     print GetKperfStatus()
 262
 263
 264 class KDCPU(object):
 265     def __init__(self, store, curidx):
 266         self.store = store
 267         self.curidx = curidx
 268         self.oldest_time = None
 269
 270
 271 def IterateKdebugEvents():
 272     """
 273     Yield events from the in-memory kdebug trace buffers.
 274     """
 275     ctrl = kern.globals.kd_ctrl_page
 276
 277     def get_kdstore(kdstorep):
 278         """
 279         See POINTER_FROM_KDSPTR.
 280         """
 281         buf = kern.globals.kd_bufs[kdstorep.buffer_index]
 282         return addressof(buf.kdsb_addr[kdstorep.offset])
 283
 284     def get_kdbuf_timestamp(kdbuf):
 285         time_cpu = kdbuf.timestamp
 286         return unsigned(time_cpu)
 287
 288     if (ctrl.kdebug_flags & xnudefines.KDBG_BFINIT) == 0:
 289         return
 290
 291     barrier_min = ctrl.oldest_time
 292
 293     if (ctrl.kdebug_flags & xnudefines.KDBG_WRAPPED) != 0:
 294         # TODO Yield a wrap event with the barrier_min timestamp.
 295         pass
 296
 297     # Set up CPU state for merging events.
 298     ncpus = ctrl.kdebug_cpus
 299     cpus = []
 300     for cpu in range(ncpus):
 301         kdstoreinfo = kern.globals.kdbip[cpu]
 302         storep = kdstoreinfo.kd_list_head
 303         store = None
 304         curidx = 0
 305         if storep.raw != xnudefines.KDS_PTR_NULL:
 306             store = get_kdstore(storep)
 307             curidx = store.kds_readlast
 308         # XXX Doesn't have the same logic to avoid un-mergeable events
 309         #     (respecting barrier_min and bufindx) as the C code.
 310
 311         cpus.append(KDCPU(store, curidx))
 312
 313     while True:
 314         earliest_time = 0xffffffffffffffff
 315         min_cpu = None
 316         for cpu in cpus:
 317             if not cpu.store:
 318                 continue
 319
 320             # Check for overrunning the writer, which also indicates the CPU is
 321             # out of events.
 322             if cpu.oldest_time:
 323                 timestamp = cpu.oldest_time
 324             else:
 325                 timestamp = get_kdbuf_timestamp(
 326                         addressof(cpu.store.kds_records[cpu.curidx]))
 327                 cpu.oldest_time = timestamp
 328
 329             if timestamp < cpu.store.kds_timestamp:
 330                 cpu.store = None
 331                 continue
 332
 333             if timestamp < earliest_time:
 334                 earliest_time = timestamp
 335                 min_cpu = cpu
 336
 337         # Out of events.
 338         if not min_cpu:
 339             return
 340
 341         yield min_cpu.store.kds_records[min_cpu.curidx]
 342         min_cpu.oldest_time = None
 343
 344         min_cpu.curidx += 1
 345         if min_cpu.curidx == xnudefines.EVENTS_PER_STORAGE_UNIT:
 346             next = min_cpu.store.kds_next
 347             if next.raw == xnudefines.KDS_PTR_NULL:
 348                 min_cpu.store = None
 349                 min_cpu.curidx = None
 350             else:
 351                 min_cpu.store = get_kdstore(next)
 352                 min_cpu.curidx = min_cpu.store.kds_readlast
 353
 354         # This CPU is out of events.
 355         if min_cpu.curidx == min_cpu.store.kds_bufindx:
 356             min_cpu.store = None
 357             continue
 358
 359
 360 def GetKdebugEvent(event):
 361     """
 362     Return a string representing a kdebug trace event.
 363     """
 364     return '{:16} {:8} {:8x} {:16} {:16} {:16} {:16} {:4} {:8} {}'.format(
 365             unsigned(event.timestamp), 0, unsigned(event.debugid),
 366             unsigned(event.arg1), unsigned(event.arg2),
 367             unsigned(event.arg3), unsigned(event.arg4), unsigned(event.cpuid),
 368             unsigned(event.arg5), "")
 369
 370
 371 @lldb_command('showkdebugtrace')
 372 def ShowKdebugTrace(cmd_args=None):
 373     """
 374     List the events present in the kdebug trace buffers.
 375
 376     (lldb) showkdebugtrace
 377
 378     Caveats:
 379         * Events from IOPs may be missing or cut-off -- they weren't informed
 380           of this kind of buffer collection.
 381     """
 382     for event in IterateKdebugEvents():
 383         print(GetKdebugEvent(event))
 384
 385
 386 @lldb_command('savekdebugtrace', 'N:')
 387 def SaveKdebugTrace(cmd_args=None, cmd_options={}):
 388     """
 389     Save any valid ktrace events to a file.
 390
 391     (lldb) savekdebugtrace [-N <n-events>] <file-to-write>
 392
 393     Caveats:
 394         * 32-bit kernels are unsupported.
 395         * The trace file will be missing machine and config chunks, which might
 396           prevent tools from analyzing it.
 397     """
 398
 399     if kern.arch not in ['x86_64', 'x86_64h', 'arm64', 'arm64e']:
 400         print('32-bit kernels are unsupported')
 401         return
 402
 403     if len(cmd_args) != 1:
 404         raise ArgumentError('path to trace file is required')
 405
 406     nevents = unsigned(kern.globals.nkdbufs)
 407     if nevents == 0:
 408         print('kdebug buffers are not set up')
 409         return
 410
 411     limit_nevents = nevents
 412     if '-N' in cmd_options:
 413         limit_nevents = unsigned(cmd_options['-N'])
 414         if limit_nevents > nevents:
 415             limit_nevents = nevents
 416     verbose = config['verbosity'] > vHUMAN
 417
 418     file_offset = 0
 419     with open(cmd_args[0], 'w+b') as f:
 420         FILE_MAGIC = 0x55aa0300
 421         EVENTS_TAG = 0x00001e00
 422         SSHOT_TAG = 0x8002
 423         CHUNKHDR_PACK = 'IHHQ'
 424         FILEHDR_PACK = CHUNKHDR_PACK + 'IIQQIIII'
 425         FILEHDR_SIZE = 40
 426         FUTURE_SIZE = 8
 427
 428         numer, denom = GetTimebaseInfo()
 429
 430         # XXX The kernel doesn't have a solid concept of the wall time.
 431         wall_abstime = 0
 432         wall_secs = 0
 433         wall_usecs = 0
 434
 435         # XXX 32-bit is NYI
 436         k64 = True
 437         event_size = unsigned(64)
 438
 439         file_hdr = struct.pack(
 440                 FILEHDR_PACK, FILE_MAGIC, 0, 0, FILEHDR_SIZE,
 441                 numer, denom, wall_abstime, wall_secs, wall_usecs, 0, 0,
 442                 0x1 if k64 else 0)
 443         f.write(file_hdr)
 444         file_offset += 16 + FILEHDR_SIZE # chunk header plus file header
 445
 446         skip_nevents = nevents - limit_nevents if limit_nevents else 0
 447         if skip_nevents > 0:
 448             print('omitting {} events from the beginning'.format(skip_nevents))
 449
 450         events_hdr = struct.pack(
 451                 CHUNKHDR_PACK, EVENTS_TAG, 0, 0, 0) # size will be filled in later
 452         f.write(events_hdr)
 453         file_offset += 16 # header size
 454         event_size_offset = file_offset - FUTURE_SIZE
 455         # Future events timestamp -- doesn't need to be set for merged events.
 456         f.write(struct.pack('Q', 0))
 457         file_offset += FUTURE_SIZE
 458
 459         if verbose:
 460             print('events start at offset {}'.format(file_offset))
 461
 462         process = LazyTarget().GetProcess()
 463         error = lldb.SBError()
 464
 465         written_nevents = 0
 466         seen_nevents = 0
 467         for event in IterateKdebugEvents():
 468             seen_nevents += 1
 469             if skip_nevents >= seen_nevents:
 470                 if seen_nevents % 1000 == 0:
 471                     sys.stderr.write('skipped {}/{} ({:4.2f}%) events'.format(
 472                             seen_nevents, skip_nevents,
 473                             float(seen_nevents) / skip_nevents * 100.0))
 474                     sys.stderr.write('\r')
 475
 476                 continue
 477
 478             event = process.ReadMemory(
 479                     unsigned(addressof(event)), event_size, error)
 480             file_offset += event_size
 481             f.write(event)
 482             written_nevents += 1
 483             # Periodically update the CLI with progress.
 484             if written_nevents % 1000 == 0:
 485                 sys.stderr.write('wrote {}/{} ({:4.2f}%) events'.format(
 486                         written_nevents, limit_nevents,
 487                         float(written_nevents) / nevents * 100.0))
 488                 sys.stderr.write('\r')
 489         sys.stderr.write('\n')
 490         print('wrote {} events'.format(written_nevents))
 491         if verbose:
 492             print('events end at offset {}'.format(file_offset))
 493
 494         # Normally, the chunk would need to be padded to 8, but events are
 495         # already aligned.
 496
 497         kcdata = kern.globals.kc_panic_data
 498         kcdata_addr = unsigned(kcdata.kcd_addr_begin)
 499         kcdata_length = unsigned(kcdata.kcd_length)
 500         if kcdata_addr != 0 and kcdata_length != 0:
 501             print('writing stackshot')
 502             f.write(struct.pack(CHUNKHDR_PACK, SSHOT_TAG, 1, 0, kcdata_length))
 503             file_offset += 16
 504             if verbose:
 505                 print('stackshot is {} bytes long'.format(kcdata_length))
 506                 print('stackshot starts at offset {}'.format(file_offset))
 507             ssdata = process.ReadMemory(kcdata_addr, kcdata_length, error)
 508             f.write(ssdata)
 509             file_offset += kcdata_length
 510             if verbose:
 511                 print('stackshot ends at offset {}'.format(file_offset))
 512         else:
 513             print('stackshot is not available, trace file may not be usable!')
 514
 515         # After the number of events is known, fix up the events chunk size.
 516         events_data_size = unsigned(written_nevents * event_size) + FUTURE_SIZE
 517         f.seek(event_size_offset)
 518         f.write(struct.pack('Q', events_data_size))
 519
 520     return