from xnu import ( kern, ArgumentError, unsigned, lldb_command, header, GetEnumValue, GetEnumValues, GetEnumName, GetThreadName, GetProcStartAbsTimeForTask, GetRecentTimestamp, GetProcNameForTask, FindTasksByName, IterateQueue) def validate_args(opts, valid_flags): valid_flags = set(valid_flags) for k in opts.keys(): if k[1:] not in valid_flags: raise ArgumentError('-{} not supported in subcommand'.format(k)) @lldb_command('recount', 'AF:MT', fancy=True) def Recount(cmd_args=None, cmd_options={}, O=None): # noqa: E741 """ Inspect counters maintained by the Recount subsystem on various resource aggregators, like tasks or threads. recount task [-TM] [...] | -F recount thread [-M] [...] recount coalition [-M] [...] recount processor [-ATM] [] [...] Options: -T : break out active threads for a task or processor -M : show times in the Mach timebase -A : show all processors Diagnostic macros: recount diagnose task - Ensure resource accounting consistency in a task. recount triage - Print out statistics useful for general panic triage. """ if not cmd_args: raise ArgumentError('subcommand required') if cmd_args[0] == 'coalition': validate_args(cmd_options, ['M']) RecountCoalition(cmd_args[1:], cmd_options=cmd_options, O=O) elif cmd_args[0] == 'task': validate_args(cmd_options, ['F', 'M', 'T']) RecountTask(cmd_args[1:], cmd_options=cmd_options, O=O) elif cmd_args[0] == 'thread': validate_args(cmd_options, ['M']) RecountThread(cmd_args[1:], cmd_options=cmd_options, O=O) elif cmd_args[0] == 'processor': validate_args(cmd_options, ['A', 'M', 'T']) RecountProcessor(cmd_args[1:], cmd_options=cmd_options, O=O) elif cmd_args[0] == 'diagnose': RecountDiagnose(cmd_args[1:], cmd_options=cmd_options, O=O) elif cmd_args[0] == 'triage': validate_args(cmd_options, []) RecountTriage(cmd_options=cmd_options, O=O) else: raise ArgumentError('{}: invalid subcommand'.format(cmd_args[0])) def scale_suffix(val, unit=''): si_units = [ (1e21, 'Z'), (1e18, 'E'), (1e15, 'P'), (1e12, 'T'), (1e9, 'B'), (1e6, 'M'), (1e3, 'k'), (1, ' '), (1e-3, 'm'), (1e-6, 'u'), (1e-9, 'n')] scale, sfx = (1, '') for (si_scale, si_sfx) in si_units: if val >= si_scale: scale, sfx = (si_scale, si_sfx) break return '{:>7.3f}{:<1s}{}'.format(val / scale, sfx, unit) class RecountSum(object): """ Accumulate usage counters. """ def __init__(self, mach_times=False): self._mach_times = mach_times self._levels = RecountPlan.levels() self._times_mach = [0] * len(self._levels) self._instructions = [0] * len(self._levels) self._cycles = [0] * len(self._levels) self._energy_nj = 0 self._valid_count = 0 def add_usage(self, usage): for (_, level) in self._levels: metrics = usage.ru_metrics[level] self._times_mach[level] += unsigned(metrics.rm_time_mach) if hasattr(metrics, 'rm_cycles'): self._instructions[level] += unsigned(metrics.rm_instructions) self._cycles[level] += unsigned(metrics.rm_cycles) if unsigned(metrics.rm_cycles) != 0: self._valid_count += 1 if hasattr(usage, 'ru_energy_nj'): self._energy_nj += unsigned(usage.ru_energy_nj) def user_sys_times(self): user_level = GetEnumValue('recount_level_t', 'RCT_LVL_USER') user_time = self._times_mach[user_level] return (user_time, sum(self._times_mach) - user_time) def div_valid(self, numer, denom): if self._valid_count == 0 or denom == 0: return 0 return numer / denom def _convert_time(self, time): if self._mach_times: return time return kern.GetNanotimeFromAbstime(time) / 1e9 def time(self): time = sum(self._times_mach) if self._mach_times: return time return kern.GetNanotimeFromAbstime(time) def fmt_args(self): level_args = [[ level_name, self._convert_time(self._times_mach[level]), scale_suffix(self._cycles[level]), self.div_valid( self._cycles[level], kern.GetNanotimeFromAbstime(self._times_mach[level])), scale_suffix(self._instructions[level]), self.div_valid(self._cycles[level], self._instructions[level]), '-', '-'] for (level_name, level) in RecountPlan.levels()] total_time_ns = kern.GetNanotimeFromAbstime(sum(self._times_mach)) total_cycles = sum(self._cycles) total_insns = sum(self._instructions) power_w = self._energy_nj / total_time_ns if total_time_ns != 0 else 0 level_args.append([ '*', total_time_ns / 1e9, scale_suffix(total_cycles), self.div_valid(total_cycles, total_time_ns), scale_suffix(total_insns), self.div_valid(total_cycles, total_insns), scale_suffix(self._energy_nj / 1e9, 'J'), scale_suffix(power_w, 'W')]) return level_args def fmt_basic_args(self): return [[ level_name, self._convert_time(self._times_mach[level]), self._cycles[level], self._instructions[level], '-'] for (level_name, level) in RecountPlan.levels()] class RecountPlan(object): """ Format tracks and usage according to a plan. """ def __init__(self, name, mach_times=False): self._mach_times = mach_times self._group_names = [] self._group_column = None plan = kern.GetGlobalVariable('recount_' + name + '_plan') topo = plan.rpl_topo if topo == GetEnumValue('recount_topo_t', 'RCT_TOPO_CPU'): self._group_column = 'cpu' self._group_count = unsigned(kern.globals.real_ncpus) self._group_names = [ 'cpu-{}'.format(i) for i in range(self._group_count)] elif topo == GetEnumValue('recount_topo_t', 'RCT_TOPO_CPU_KIND'): if kern.arch.startswith('arm64'): self._group_column = 'cpu-kind' cluster_mask = int(kern.globals.topology_info.cluster_types) self._group_count = bin(cluster_mask).count('1') self._group_names = [ GetEnumName('recount_cpu_kind_t', i)[8:][:4] for i in range(self._group_count)] else: self._group_count = 1 elif topo == GetEnumValue('recount_topo_t', 'RCT_TOPO_SYSTEM'): self._group_count = 1 else: raise RuntimeError('{}: Unexpected recount topography', topo) def time_fmt(self): return '{:>12d}' if self._mach_times else '{:>12.05f}' def _usage_fmt(self): prefix = '{n}{{:>6s}} {t} '.format( t=self.time_fmt(), n='{:>8s} ' if self._group_column else '') return prefix + '{:>8s} {:>7.3g} {:>8s} {:>5.03f} {:>9s} {:>9s}' def usages(self, usages): for i in range(self._group_count): yield usages[i] def track_usages(self, tracks): for i in range(self._group_count): yield tracks[i].rt_usage def usage_header(self): fmt = '{:>6s} {:>12s} {:>8s} {:>7s} {:>8s} {:>5s} {:>9s} {:>9s}'.format( # noqa: E501 'level', 'time', 'cycles', 'GHz', 'insns', 'CPI', 'energy', 'power',) if self._group_column: fmt = '{:>8s} '.format(self._group_column) + fmt return fmt def levels(): names = ['kernel', 'user'] levels = list(zip(names, GetEnumValues('recount_level_t', [ 'RCT_LVL_' + name.upper() for name in names]))) try: levels.append(('secure', GetEnumValue('recount_level_t', 'RCT_LVL_SECURE'))) except KeyError: # RCT_LVL_SECURE is not defined on this system. pass return levels def format_usage(self, usage, name=None, sum=None, O=None): rows = [] levels = RecountPlan.levels() total_time = 0 total_time_ns = 0 total_cycles = 0 total_insns = 0 for (level_name, level) in levels: metrics = usage.ru_metrics[level] time = unsigned(metrics.rm_time_mach) time_ns = kern.GetNanotimeFromAbstime(time) total_time_ns += time_ns if not self._mach_times: time = time_ns / 1e9 total_time += time if hasattr(metrics, 'rm_cycles'): cycles = unsigned(metrics.rm_cycles) total_cycles += cycles freq = cycles / time_ns if time_ns != 0 else 0 insns = unsigned(metrics.rm_instructions) total_insns += insns cpi = cycles / insns if insns != 0 else 0 else: cycles = 0 freq = 0 insns = 0 cpi = 0 rows.append([ level_name, time, scale_suffix(cycles), freq, scale_suffix(insns), cpi, '-', '-']) if hasattr(usage, 'ru_energy_nj'): energy_nj = unsigned(usage.ru_energy_nj) if total_time_ns != 0: power_w = energy_nj / total_time_ns else: power_w = 0 else: energy_nj = 0 power_w = 0 if total_insns != 0: total_freq = total_cycles / total_time_ns if total_time_ns != 0 else 0 total_cpi = total_cycles / total_insns else: total_freq = 0 total_cpi = 0 rows.append([ '*', total_time, scale_suffix(total_cycles), total_freq, scale_suffix(total_insns), total_cpi, scale_suffix(energy_nj / 1e9, 'J'), scale_suffix(power_w, 'W')]) if sum: sum.add_usage(usage) if self._group_column: for row in rows: row.insert(0, name) return [O.format(self._usage_fmt(), *row) for row in rows] def format_sum(self, sum, O=None): lines = [] for line in sum.fmt_args(): lines.append(O.format(self._usage_fmt(), '*', *line)) return lines def format_usages(self, usages, O=None): # noqa: E741 sum = RecountSum(self._mach_times) if self._group_count > 1 else None str = '' for (i, usage) in enumerate(self.usages(usages)): name = self._group_names[i] if i < len(self._group_names) else None lines = self.format_usage(usage, name=name, sum=sum, O=O) str += '\n'.join(lines) + '\n' if sum: str += '\n'.join(self.format_sum(sum, O=O)) return str def format_tracks(self, tracks, O=None): # noqa: E741 sum = RecountSum(self._mach_times) if self._group_count > 1 else None str = '' for (i, usage) in enumerate(self.track_usages(tracks)): name = self._group_names[i] if i < len(self._group_names) else None lines = self.format_usage(usage, name=name, sum=sum, O=O) str += '\n'.join(lines) + '\n' if sum: str += '\n'.join(self.format_sum(sum, O=O)) return str def sum_usages(self, usages, sum=None): if sum is None: sum = RecountSum(mach_times=self._mach_times) for usage in self.usages(usages): sum.add_usage(usage) return sum def sum_tracks(self, tracks, sum=None): if sum is None: sum = RecountSum(mach_times=self._mach_times) for usage in self.track_usages(tracks): sum.add_usage(usage) return sum def GetTaskTerminatedUserSysTime(task): plan = RecountPlan('task_terminated') sum = RecountSum() for usage in plan.usages(task.tk_recount.rtk_terminated): sum.add_usage(usage) return sum.user_sys_times() def GetThreadUserSysTime(thread): plan = RecountPlan('thread') sum = RecountSum() for usage in plan.track_usages(thread.th_recount.rth_lifetime): sum.add_usage(usage) return sum.user_sys_times() def print_threads(plan, thread_ptrs, indent=False, O=None): # noqa: E741 for thread_ptr in thread_ptrs: thread = kern.GetValueFromAddress(thread_ptr, 'thread_t') print('{}thread 0x{:x} 0x{:x} {}'.format( ' ' if indent else '', unsigned(thread.thread_id), unsigned(thread), GetThreadName(thread))) with O.table(plan.usage_header(), indent=indent): print(plan.format_tracks(thread.th_recount.rth_lifetime, O=O)) def RecountThread( thread_ptrs, cmd_options={}, indent=False, O=None): # noqa: E741 plan = RecountPlan('thread', mach_times='-M' in cmd_options) print_threads(plan, thread_ptrs, indent=indent, O=O) def get_task_age_ns(task): start_abs = GetProcStartAbsTimeForTask(task) if start_abs is not None: return kern.GetNanotimeFromAbstime(GetRecentTimestamp() - start_abs) return None def print_task_description(task): task_name = GetProcNameForTask(task) task_age_ns = get_task_age_ns(task) if task_age_ns is not None: duration_desc = '{:.3f}s'.format(task_age_ns / 1e9) else: duration_desc = '-s' print('task 0x{:x} {} ({} old)'.format( unsigned(task), task_name, duration_desc)) return task_name def RecountTask(task_ptrs, cmd_options={}, O=None): # noqa: E741 if '-F' in cmd_options: tasks = FindTasksByName(cmd_options['-F']) else: tasks = [kern.GetValueFromAddress(t, 'task_t') for t in task_ptrs] mach_times = '-M' in cmd_options plan = RecountPlan('task', mach_times=mach_times) terminated_plan = RecountPlan('task_terminated', mach_times=mach_times) active_threads = '-T' in cmd_options if active_threads: thread_plan = RecountPlan('thread', mach_times=mach_times) for task in tasks: task_name = print_task_description(task) with O.table(plan.usage_header()): print(plan.format_tracks(task.tk_recount.rtk_lifetime, O=O)) if active_threads: threads = [unsigned(t) for t in IterateQueue( task.threads, 'thread *', 'task_threads')] print_threads(thread_plan, threads, indent=True, O=O) print('task (terminated threads) 0x{:x} {}'.format( unsigned(task), task_name)) with O.table(terminated_plan.usage_header()): print(terminated_plan.format_usages( task.tk_recount.rtk_terminated, O=O)) def RecountCoalition(coal_ptrs, cmd_options={}, O=None): # noqa: E741 plan = RecountPlan('coalition', mach_times='-M' in cmd_options) coals = [kern.GetValueFromAddress(c, 'coalition_t') for c in coal_ptrs] for coal in coals: print('coalition 0x{:x} {}'.format(unsigned(coal), unsigned(coal.id))) with O.table(plan.usage_header()): print(plan.format_usages(coal.r.co_recount.rco_exited, O=O)) def get_processor(ptr_or_id): ptr_or_id = unsigned(ptr_or_id) if ptr_or_id < 1024: processor_list = kern.GetGlobalVariable('processor_list') current_processor = processor_list while unsigned(current_processor) > 0: if unsigned(current_processor.cpu_id) == ptr_or_id: return current_processor current_processor = current_processor.processor_list raise ArgumentError('no processor found with CPU ID {}'.format( ptr_or_id)) else: return kern.GetValueFromAddress(ptr_or_id, 'processor_t') def get_all_processors(): processors = [] processor_list = kern.GetGlobalVariable('processor_list') current_processor = processor_list while unsigned(current_processor) > 0: processors.append(current_processor) current_processor = current_processor.processor_list return sorted(processors, key=lambda p: p.cpu_id) def RecountProcessor(pr_ptrs_or_ids, cmd_options={}, O=None): # noqa: E741 mach_times = '-M' in cmd_options plan = RecountPlan('processor', mach_times=mach_times) if '-A' in cmd_options: prs = get_all_processors() else: prs = [get_processor(p) for p in pr_ptrs_or_ids] active_threads = '-T' in cmd_options if active_threads: thread_plan = RecountPlan('thread', mach_times=mach_times) hdr_prefix = '{:>18s} {:>4s} {:>4s} '.format('processor', 'cpu', 'kind',) header_fmt = ' {:>12s} {:>12s} {:>8s}' hdr_suffix = header_fmt.format('idle-time', 'total-time', 'idle-pct') null_suffix = header_fmt.format('-', '-', '-') levels = RecountPlan.levels() with O.table(hdr_prefix + plan.usage_header() + hdr_suffix): for pr in prs: usage = pr.pr_recount.rpr_active.rt_usage idle_time = pr.pr_recount.rpr_idle_time_mach times = [usage.ru_metrics[i].rm_time_mach for (_, i) in levels] total_time = sum(times) + idle_time if not mach_times: idle_time = kern.GetNanotimeFromAbstime(idle_time) / 1e9 total_time = kern.GetNanotimeFromAbstime(total_time) / 1e9 kind = 'SMP' pset = pr.processor_set if unsigned(pset.pset_cluster_type) == 1: kind = 'E' elif unsigned(pset.pset_cluster_type) == 2: kind = 'P' prefix = '{:<#018x} {:>4d} {:>4s} '.format( unsigned(pr), pr.cpu_id, kind) suffix = ( ' ' + plan.time_fmt().format(idle_time) + ' ' + plan.time_fmt().format(total_time) + ' {:>7.2f}%'.format(idle_time / total_time * 100)) usage_lines = plan.format_usage(usage, O=O) for (i, line) in enumerate(usage_lines): line_suffix = null_suffix if i + 1 == len(usage_lines): line_suffix = suffix O.write(prefix + line + line_suffix + '\n') if active_threads: active_thread = unsigned(pr.active_thread) if active_thread != 0: print_threads( thread_plan, [active_thread], indent=True, O=O) @header('{:>4s} {:>20s} {:>20s} {:>20s}'.format( 'cpu', 'time-mach', 'cycles', 'insns')) def GetRecountSnapshot(cpu, snap, O=None): (insns, cycles) = (0, 0) if hasattr(snap, 'rsn_cycles'): (insns, cycles) = (snap.rsn_insns, snap.rsn_cycles) return O.format( '{:4d} {:20d} {:20d} {:20d}', cpu, snap.rsn_time_mach, cycles, insns) def GetRecountProcessorState(pr): state_time = pr.pr_recount.rpr_state_last_abs_time state = state_time >> 63 return ( pr.pr_recount.rpr_snap, 'I' if state == 1 else 'A', state_time & ~(0x1 << 63)) @header('{:>20s} {:>4s} {:>6s} {:>18s} {:>18s} {:>18s} {:>18s} {:>18s}'.format( 'processor', 'cpu', 'state', 'last-idle-change', 'last-user-change', 'last-disp', 'since-idle-change', 'since-user-change')) def GetRecountProcessorDiagnostics(pr, cur_time, O=None): (snap, state, time) = GetRecountProcessorState(pr) cpu_id = unsigned(pr.cpu_id) last_usrchg = snap.rsn_time_mach since_usrchg = cur_time - last_usrchg last_disp = '{}{:>d}'.format( '*' if cur_time == unsigned(pr.last_dispatch) else '', pr.last_dispatch) return O.format( '{:>#20x} {:4d} {:>6s} {:>18d} {:>18d} {:>18s} {:>18d} {:>18d}', unsigned(pr), cpu_id, state, time, last_usrchg, last_disp, cur_time - time, since_usrchg) @header('{:>12s} {:>6s} {:>12s} {:>20s} {:>20s}'.format( 'group', 'level', 'time', 'cycles', 'insns')) def RecountDiagnoseTask(task_ptrs, cmd_options={}, O=None): # noqa: E74 if '-F' in cmd_options: tasks = FindTasksByName(cmd_options['-F']) else: tasks = [kern.GetValueFromAddress(t, 'task_t') for t in task_ptrs] line_fmt = '{:20s} = {:10.3f}' row_fmt = '{:>12s} {:>6s} {:>12.3f} {:>20d} {:>20d}' task_plan = RecountPlan('task', mach_times=False) term_plan = RecountPlan('task_terminated', mach_times=False) for task in tasks: print_task_description(task) with O.table(RecountDiagnoseTask.header): task_sum = task_plan.sum_tracks(task.tk_recount.rtk_lifetime) for line in task_sum.fmt_basic_args(): line = line[:-1] print(O.format(row_fmt, 'task', *line)) term_sum = term_plan.sum_usages(task.tk_recount.rtk_terminated) for line in term_sum.fmt_basic_args(): print(O.format(row_fmt, 'terminated', *line)) term_sum_ns = term_sum.time() threads_sum = RecountSum(mach_times=True) threads_time_mach = threads_sum.time() for thread in IterateQueue( task.threads, 'thread *', 'task_threads'): usr_time, sys_time = GetThreadUserSysTime(thread) threads_time_mach += usr_time + sys_time threads_sum_ns = kern.GetNanotimeFromAbstime(threads_time_mach) print(line_fmt.format('threads CPU', threads_sum_ns / 1e9)) all_threads_sum_ns = threads_sum_ns + term_sum_ns print(line_fmt.format('all threads CPU', all_threads_sum_ns / 1e9)) print(line_fmt.format( 'discrepancy', task_sum.time() - all_threads_sum_ns)) def RecountDiagnose(cmd_args=[], cmd_options={}, O=None): # noqa: E741 if not cmd_args: raise ArgumentError('diagnose subcommand required') if cmd_args[0] == 'task': validate_args(cmd_options, ['F']) RecountDiagnoseTask(cmd_args[1:], cmd_options=cmd_options, O=O) else: raise ArgumentError('{}: invalid diagnose subcommand'.format( cmd_args[0])) def RecountTriage(cmd_options={}, O=None): # noqa: E741 prs = get_all_processors() print('processors') with O.table(GetRecountProcessorDiagnostics.header, indent=True): max_dispatch = max([unsigned(pr.last_dispatch) for pr in prs]) for pr in prs: print(GetRecountProcessorDiagnostics( pr, cur_time=max_dispatch, O=O)) print('snapshots') with O.table(GetRecountSnapshot.header, indent=True): for (i, pr) in enumerate(prs): print(GetRecountSnapshot(i, pr.pr_recount.rpr_snap, O=O))