tools/lldbmacros/ktrace.py

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