1from __future__ import absolute_import, division, print_function 2 3from xnu import * 4 5 6def validate_args(opts, valid_flags): 7 valid_flags = set(valid_flags) 8 for k in opts.keys(): 9 if k[1:] not in valid_flags: 10 raise ArgumentError('-{} not supported in subcommand'.format(k)) 11 12 13@lldb_command('recount', 'AF:MT', fancy=True) 14def Recount(cmd_args=None, cmd_options={}, O=None): # noqa: E741 15 """ Inspect counters maintained by the Recount subsystem on various resource 16 aggregators, like tasks or threads. 17 18 recount task [-TM] <task_t> [...] | -F <task_name> 19 recount thread [-M] <thread_t> [...] 20 recount coalition [-M] <coalition_t> [...] 21 recount processor [-ATM] [<processor_t-or-cpu-id>] [...] 22 23 Options: 24 -T : break out active threads for a task or processor 25 -M : show times in the Mach timebase 26 -A : show all processors 27 28 Diagnostic macros: 29 recount diagnose task <task_t> 30 - Ensure resource accounting consistency in a task. 31 recount triage 32 - Print out statistics useful for general panic triage. 33 34 """ 35 if not cmd_args: 36 raise ArgumentError('subcommand required') 37 38 if cmd_args[0] == 'coalition': 39 validate_args(cmd_options, ['M']) 40 RecountCoalition(cmd_args[1:], cmd_options=cmd_options, O=O) 41 elif cmd_args[0] == 'task': 42 validate_args(cmd_options, ['F', 'M', 'T']) 43 RecountTask(cmd_args[1:], cmd_options=cmd_options, O=O) 44 elif cmd_args[0] == 'thread': 45 validate_args(cmd_options, ['M']) 46 RecountThread(cmd_args[1:], cmd_options=cmd_options, O=O) 47 elif cmd_args[0] == 'processor': 48 validate_args(cmd_options, ['A', 'M', 'T']) 49 RecountProcessor(cmd_args[1:], cmd_options=cmd_options, O=O) 50 elif cmd_args[0] == 'diagnose': 51 RecountDiagnose(cmd_args[1:], cmd_options=cmd_options, O=O) 52 elif cmd_args[0] == 'triage': 53 validate_arg(cmd_options, []) 54 RecountTriage(cmd_options=cmd_options, O=O) 55 else: 56 raise ArgumentError('{}: invalid subcommand'.format(cmd_args[0])) 57 58 59def scale_suffix(val, unit=''): 60 si_units = [ 61 (1e21, 'Z'), (1e18, 'E'), (1e15, 'P'), (1e12, 'T'), (1e9, 'B'), 62 (1e6, 'M'), (1e3, 'k'), (1, ' '), (1e-3, 'm'), (1e-6, 'u'), 63 (1e-9, 'n')] 64 scale, sfx = (1, '') 65 for (si_scale, si_sfx) in si_units: 66 if val >= si_scale: 67 scale, sfx = (si_scale, si_sfx) 68 break 69 return '{:>7.3f}{:<1s}{}'.format(val / scale, sfx, unit) 70 71 72class RecountSum(object): 73 """ 74 Accumulate usage counters. 75 """ 76 77 def __init__(self, mach_times=False): 78 self._mach_times = mach_times 79 self._user_time_mach = 0 80 self._system_time_mach = 0 81 self._instructions = 0 82 self._cycles = 0 83 self._energy_nj = 0 84 self._valid_count = 0 85 86 def add_usage(self, usage): 87 self._user_time_mach += unsigned(usage.ru_user_time_mach) 88 self._system_time_mach += unsigned(usage.ru_system_time_mach) 89 if hasattr(usage, 'ru_cycles'): 90 self._instructions += unsigned(usage.ru_instructions) 91 self._cycles += unsigned(usage.ru_cycles) 92 if unsigned(usage.ru_cycles) != 0: 93 self._valid_count += 1 94 if hasattr(usage, 'ru_energy_nj'): 95 self._energy_nj += unsigned(usage.ru_energy_nj) 96 97 def user_sys_times(self): 98 return (self._user_time_mach, self._system_time_mach) 99 100 def div_valid(self, numer, denom): 101 if self._valid_count == 0 or denom == 0: 102 return 0 103 return numer / denom 104 105 def _convert_time(self, time): 106 if self._mach_times: 107 return time 108 return kern.GetNanotimeFromAbstime(time) / 1e9 109 110 def fmt_args(self): 111 time_ns = kern.GetNanotimeFromAbstime( 112 self._system_time_mach + self._user_time_mach) 113 power_w = self._energy_nj / time_ns if time_ns != 0 else 0 114 return [ 115 self._convert_time(self._system_time_mach), 116 self._convert_time(self._user_time_mach), 117 scale_suffix(self._cycles), 118 self.div_valid(self._cycles, time_ns), 119 scale_suffix(self._instructions), 120 self.div_valid(self._cycles, self._instructions), 121 scale_suffix(self._energy_nj / 1e9, 'J'), 122 scale_suffix(power_w, 'W')] 123 124 def fmt_basic_args(self): 125 return [ 126 self._convert_time(self._system_time_mach), 127 self._convert_time(self._user_time_mach), 128 self._cycles, 129 self._instructions, 130 self._energy_nj / 1e9] 131 132 133 134class RecountPlan(object): 135 """ 136 Format tracks and usage according to a plan. 137 """ 138 139 def __init__(self, name, mach_times=False): 140 self._mach_times = mach_times 141 self._group_names = [] 142 self._group_column = None 143 144 plan = kern.GetGlobalVariable('recount_' + name + '_plan') 145 topo = plan.rpl_topo 146 if topo == GetEnumValue('recount_topo_t::RCT_TOPO_CPU'): 147 self._group_column = 'cpu' 148 self._group_count = unsigned(kern.globals.real_ncpus) 149 self._group_names = [ 150 'cpu-{}'.format(i) for i in range(self._group_count)] 151 elif topo == GetEnumValue('recount_topo_t::RCT_TOPO_CPU_KIND'): 152 if kern.arch.startswith('arm64'): 153 self._group_column = 'cpu-kind' 154 cluster_mask = int(kern.globals.topology_info.cluster_types) 155 self._group_count = bin(cluster_mask).count('1') 156 self._group_names = [ 157 GetEnumName('recount_cpu_kind_t', i)[8:][:4] 158 for i in range(self._group_count)] 159 else: 160 self._group_count = 1 161 elif topo == GetEnumValue('recount_topo_t::RCT_TOPO_SYSTEM'): 162 self._group_count = 1 163 else: 164 raise RuntimeError('{}: Unexpected recount topography', topo) 165 166 def time_fmt(self): 167 return '{:>12d}' if self._mach_times else '{:>12.05f}' 168 169 def _usage_fmt(self): 170 prefix = '{n}{t} {t}'.format( 171 t=self.time_fmt(), n='{:>8s} ' if self._group_column else '') 172 return prefix + ' {:>8s} {:>7.3g} {:>8s} {:>5.03f} {:>9s} {:>9s}' 173 174 def usages(self, usages): 175 for i in range(self._group_count): 176 yield usages[i] 177 178 def track_usages(self, tracks): 179 for i in range(self._group_count): 180 yield tracks[i].rt_usage 181 182 def usage_header(self): 183 fmt = '{:>12s} {:>12s} {:>8s} {:>7s} {:>8s} {:>5s} {:>9s} {:>9s}'.format( 184 'sys-time', 'user-time', 'cycles', 'GHz', 'insns', 'CPI', 185 'energy', 'power',) 186 if self._group_column: 187 fmt = '{:>8s} '.format(self._group_column) + fmt 188 return fmt 189 190 def format_usage(self, usage, name=None, sum=None, O=None): 191 usr_time = unsigned(usage.ru_user_time_mach) 192 usr_time_ns = kern.GetNanotimeFromAbstime(usr_time) 193 sys_time = unsigned(usage.ru_system_time_mach) 194 sys_time_ns = kern.GetNanotimeFromAbstime(sys_time) 195 all_time_ns = usr_time_ns + sys_time_ns 196 if not self._mach_times: 197 usr_time = usr_time_ns / 1e9 198 if not self._mach_times: 199 sys_time = sys_time_ns / 1e9 200 if hasattr(usage, 'ru_cycles'): 201 cycles = unsigned(usage.ru_cycles) 202 freq = cycles / all_time_ns if all_time_ns != 0 else 0 203 insns = unsigned(usage.ru_instructions) 204 cpi = cycles / insns if insns != 0 else 0 205 else: 206 cycles = 0 207 freq = 0 208 insns = 0 209 cpi = 0 210 if hasattr(usage, 'ru_energy_nj'): 211 energy_nj = unsigned(usage.ru_energy_nj) 212 time_ns = usr_time_ns + sys_time_ns 213 if time_ns != 0: 214 power_w = energy_nj / time_ns 215 else: 216 power_w = 0 217 else: 218 energy_nj = 0 219 power_w = 0 220 if sum: 221 sum.add_usage(usage) 222 223 args = [ 224 sys_time, usr_time, scale_suffix(cycles), freq, 225 scale_suffix(insns), cpi, scale_suffix(energy_nj / 1e9, 'J'), 226 scale_suffix(power_w, 'W')] 227 if self._group_column: 228 args.insert(0, name) 229 230 return O.format(self._usage_fmt(), *args) 231 232 def format_sum(self, sum, O=None): 233 return O.format(self._usage_fmt(), '*', *sum.fmt_args()) 234 235 def format_usages(self, usages, O=None): # noqa: E741 236 sum = RecountSum(self._mach_times) if self._group_count > 1 else None 237 str = '' 238 for (i, usage) in enumerate(self.usages(usages)): 239 name = self._group_names[i] if i < len(self._group_names) else None 240 str += self.format_usage(usage, name=name, sum=sum, O=O) + '\n' 241 if sum: 242 str += self.format_sum(sum, O=O) 243 return str 244 245 def format_tracks(self, tracks, newlines=True, O=None): # noqa: E741 246 sum = RecountSum(self._mach_times) if self._group_count > 1 else None 247 str = '' 248 nl = '\n' if newlines else '' 249 for (i, usage) in enumerate(self.track_usages(tracks)): 250 name = self._group_names[i] if i < len(self._group_names) else None 251 str += self.format_usage(usage, name=name, sum=sum, O=O) + nl 252 if sum: 253 str += self.format_sum(sum, O=O) 254 return str 255 256 def sum_usages(self, usages, sum=None): 257 if sum is None: 258 sum = RecountSum(mach_times=self._mach_times) 259 for usage in self.usages(usages): 260 sum.add_usage(usage) 261 return sum 262 263 def sum_tracks(self, tracks, sum=None): 264 if sum is None: 265 sum = RecountSum(mach_times=self._mach_times) 266 for usage in self.track_usages(tracks): 267 sum.add_usage(usage) 268 return sum 269 270 271def GetTaskTerminatedUserSysTime(task): 272 plan = RecountPlan('task_terminated') 273 sum = RecountSum() 274 for usage in plan.usages(task.tk_recount.rtk_terminated): 275 sum.add_usage(usage) 276 return sum.user_sys_times() 277 278 279def GetThreadUserSysTime(thread): 280 plan = RecountPlan('thread') 281 sum = RecountSum() 282 for usage in plan.track_usages(thread.th_recount.rth_lifetime): 283 sum.add_usage(usage) 284 return sum.user_sys_times() 285 286 287def print_threads(plan, thread_ptrs, indent=False, O=None): # noqa: E741 288 for thread_ptr in thread_ptrs: 289 thread = kern.GetValueFromAddress(thread_ptr, 'thread_t') 290 print('{}thread 0x{:x} 0x{:x} {}'.format( 291 ' ' if indent else '', unsigned(thread.thread_id), 292 unsigned(thread), GetThreadName(thread))) 293 with O.table(plan.usage_header(), indent=indent): 294 print(plan.format_tracks(thread.th_recount.rth_lifetime, O=O)) 295 296 297def RecountThread( 298 thread_ptrs, cmd_options={}, indent=False, O=None): # noqa: E741 299 plan = RecountPlan('thread', mach_times='-M' in cmd_options) 300 print_threads(plan, thread_ptrs, indent=indent, O=O) 301 302 303def get_task_age_ns(task): 304 start_abs = GetProcStartAbsTimeForTask(task) 305 if start_abs is not None: 306 return kern.GetNanotimeFromAbstime(GetRecentTimestamp() - start_abs) 307 return None 308 309 310def print_task_description(task): 311 task_name = GetProcNameForTask(task) 312 task_age_ns = get_task_age_ns(task) 313 if task_age_ns is not None: 314 duration_desc = '{:.3f}s'.format(task_age_ns / 1e9) 315 else: 316 duration_desc = '-s' 317 print('task 0x{:x} {} ({} old)'.format( 318 unsigned(task), task_name, duration_desc)) 319 320 321def RecountTask(task_ptrs, cmd_options={}, O=None): # noqa: E741 322 if '-F' in cmd_options: 323 tasks = FindTasksByName(cmd_options['-F']) 324 else: 325 tasks = [kern.GetValueFromAddress(t, 'task_t') for t in task_ptrs] 326 mach_times = '-M' in cmd_options 327 plan = RecountPlan('task', mach_times=mach_times) 328 terminated_plan = RecountPlan('task_terminated', mach_times=mach_times) 329 active_threads = '-T' in cmd_options 330 if active_threads: 331 thread_plan = RecountPlan('thread', mach_times=mach_times) 332 for task in tasks: 333 print_task_description(task) 334 with O.table(plan.usage_header()): 335 print(plan.format_tracks(task.tk_recount.rtk_lifetime, O=O)) 336 if active_threads: 337 threads = [unsigned(t) for t in IterateQueue( 338 task.threads, 'thread *', 'task_threads')] 339 print_threads(thread_plan, threads, indent=True, O=O) 340 print('task (terminated threads) 0x{:x} {}'.format( 341 unsigned(task), task_name)) 342 with O.table(terminated_plan.usage_header()): 343 print(terminated_plan.format_usages( 344 task.tk_recount.rtk_terminated, O=O)) 345 346 347def RecountCoalition(coal_ptrs, cmd_options={}, O=None): # noqa: E741 348 plan = RecountPlan('coalition', mach_times='-M' in cmd_options) 349 coals = [kern.GetValueFromAddress(c, 'coalition_t') for c in coal_ptrs] 350 for coal in coals: 351 print('coalition 0x{:x} {}'.format(unsigned(coal), unsigned(coal.id))) 352 with O.table(plan.usage_header()): 353 print(plan.format_usages(coal.r.co_recount.rco_exited, O=O)) 354 355 356def get_processor(ptr_or_id): 357 ptr_or_id = unsigned(ptr_or_id) 358 if ptr_or_id < 1024: 359 processor_list = kern.GetGlobalVariable('processor_list') 360 current_processor = processor_list 361 while unsigned(current_processor) > 0: 362 if unsigned(current_processor.cpu_id) == ptr_or_id: 363 return current_processor 364 current_processor = current_processor.processor_list 365 raise ArgumentError('no processor found with CPU ID {}'.format( 366 ptr_or_id)) 367 else: 368 return kern.GetValueFromAddress(ptr_or_id, 'processor_t') 369 370 371def get_all_processors(): 372 processors = [] 373 processor_list = kern.GetGlobalVariable('processor_list') 374 current_processor = processor_list 375 while unsigned(current_processor) > 0: 376 processors.append(current_processor) 377 current_processor = current_processor.processor_list 378 return sorted(processors, key=lambda p: p.cpu_id) 379 380 381def RecountProcessor(pr_ptrs_or_ids, cmd_options={}, O=None): # noqa: E741 382 mach_times = '-M' in cmd_options 383 plan = RecountPlan('processor', mach_times=mach_times) 384 if '-A' in cmd_options: 385 prs = get_all_processors() 386 else: 387 prs = [get_processor(p) for p in pr_ptrs_or_ids] 388 active_threads = '-T' in cmd_options 389 if active_threads: 390 thread_plan = RecountPlan('thread', mach_times=mach_times) 391 hdr_prefix = '{:>18s} {:>4s} {:>4s} '.format('processor', 'cpu', 'kind',) 392 hdr_suffix = ' {:>12s} {:>12s} {:>8s}'.format( 393 'idle-time', 'total-time', 'idle-pct') 394 with O.table(hdr_prefix + plan.usage_header() + hdr_suffix): 395 for pr in prs: 396 usage = pr.pr_recount.rpr_active.rt_usage 397 idle_time = pr.pr_recount.rpr_idle_time_mach 398 total_time = ( 399 usage.ru_system_time_mach + usage.ru_user_time_mach + 400 idle_time) 401 if not mach_times: 402 idle_time = kern.GetNanotimeFromAbstime(idle_time) / 1e9 403 total_time = kern.GetNanotimeFromAbstime(total_time) / 1e9 404 kind = 'SMP' 405 pset = pr.processor_set 406 if unsigned(pset.pset_cluster_type) == 1: 407 kind = 'E' 408 elif unsigned(pset.pset_cluster_type) == 2: 409 kind = 'P' 410 411 prefix = '{:<#018x} {:>4d} {:>4s} '.format( 412 unsigned(pr), pr.cpu_id, kind) 413 suffix = ( 414 ' ' + plan.time_fmt().format(idle_time) + ' ' + 415 plan.time_fmt().format(total_time) + 416 ' {:>7.2f}%'.format(idle_time / total_time * 100)) 417 O.write(prefix + plan.format_usage(usage, O=O) + suffix + '\n') 418 if active_threads: 419 active_thread = unsigned(pr.active_thread) 420 if active_thread != 0: 421 print_threads( 422 thread_plan, [active_thread], indent=True, O=O) 423 424 425@header('{:>4s} {:>20s} {:>20s} {:>20s}'.format( 426 'cpu', 'time-mach', 'cycles', 'insns')) 427def GetRecountSnapshot(cpu, snap, O=None): 428 (insns, cycles, energy) = (0, 0, 0) 429 if hasattr(snap, 'rsn_cycles'): 430 (insns, cycles) = (snap.rsn_insns, snap.rsn_cycles) 431 return O.format( 432 '{:4d} {:20d} {:20d} {:20d}', cpu, snap.rsn_time_mach, 433 cycles, insns) 434 435 436def GetRecountProcessorState(pr): 437 state_time = pr.pr_recount.rpr_state_last_abs_time 438 state = state_time >> 63 439 return ('I' if state == 1 else 'A', state_time & ~(0x1 << 63)) 440 441 442@header('{:>20s} {:>4s} {:>6s} {:>18s} {:>18s} {:>18s} {:>18s} {:>18s}'.format( 443 'processor', 'cpu', 'state', 'last-idle-change', 'last-user-change', 444 'last-disp', 'since-idle-change', 'since-user-change')) 445def GetRecountProcessorDiagnostics(pr, cur_time, O=None): 446 (state, time) = GetRecountProcessorState(pr) 447 cpu_id = unsigned(pr.cpu_id) 448 snap = kern.PERCPU_GET('_snaps_percpu', cpu_id) 449 last_usrchg = snap.rsn_time_mach 450 since_usrchg = cur_time - last_usrchg 451 last_disp = '{}{:>d}'.format( 452 '*' if cur_time == unsigned(pr.last_dispatch) else '', 453 pr.last_dispatch) 454 return O.format( 455 '{:>#20x} {:4d} {:>6s} {:>18d} {:>18d} {:>18s} {:>18d} {:>18d}', 456 unsigned(pr), cpu_id, state, time, last_usrchg, last_disp, 457 cur_time - time, since_usrchg) 458 459 460@header('{:>12s} {:>12s} {:>12s} {:>20s} {:>20s} {:>12s}'.format( 461 'group', 'sys-time', 'user-time', 'cycles', 'insns', 'energy')) 462def RecountDiagnoseTask(task_ptrs, cmd_options={}, O=None): # noqa: E74 463 if '-F' in cmd_options: 464 tasks = FindTasksByName(cmd_options['-F']) 465 else: 466 tasks = [kern.GetValueFromAddress(t, 'task_t') for t in task_ptrs] 467 468 line_fmt = '{:12s} = {:10.3f}' 469 row_fmt = '{:>12s} {:>12.3f} {:>12.3f} {:>20d} {:20d} {:12.3f}' 470 471 task_plan = RecountPlan('task', mach_times=False) 472 term_plan = RecountPlan('task_terminated', mach_times=False) 473 thread_plan = RecountPlan('thread', mach_times=False) 474 for task in tasks: 475 print_task_description(task) 476 with O.table(RecountDiagnoseTask.header): 477 task_sum = task_plan.sum_tracks(task.tk_recount.rtk_lifetime) 478 print(O.format(row_fmt, 'task', *task_sum.fmt_basic_args())) 479 480 term_sum = term_plan.sum_usages(task.tk_recount.rtk_terminated) 481 print(O.format(row_fmt, 'terminated', *term_sum.fmt_basic_args())) 482 483 threads_sum = RecountSum(mach_times=False) 484 for thread in IterateQueue(task.threads, 'thread *', 'task_threads'): 485 usr_time, sys_time = GetThreadUserSysTime(thread) 486 threads_sum_mach += usr_time + sys_time 487 488 threads_sum_ns = kern.GetNanotimeFromAbstime(threads_sum_mach) 489 print(line_fmt.format('threads CPU', threads_sum_ns / 1e9)) 490 491 all_threads_sum_ns = threads_sum_ns + terminated_threads_sum_ns 492 print(line_fmt.format('all threads CPU', all_threads_sum_ns / 1e9)) 493 494 print(line_fmt.format('discrepancy', task_sum_ns - all_threads_sum_ns)) 495 496 497def RecountDiagnose(cmd_args=[], cmd_options={}, O=None): # noqa: E741 498 if not cmd_args: 499 raise ArgumentError('diagnose subcommand required') 500 501 if cmd_args[0] == 'task': 502 validate_args(cmd_options, ['F']) 503 RecountDiagnoseTask(cmd_args[0], cmd_options=cmd_options, O=O) 504 else: 505 raise ArgumentError('{}: invalid diagnose subcommand'.format( 506 cmd_args[0])) 507 508 509def RecountTriage(cmd_options={}, O=None): # noqa: E741 510 prs = get_all_processors() 511 print('processors') 512 with O.table(GetRecountProcessorDiagnostics.header, indent=True): 513 max_dispatch = max([unsigned(pr.last_dispatch) for pr in prs]) 514 for pr in prs: 515 print(GetRecountProcessorDiagnostics( 516 pr, cur_time=max_dispatch, O=O)) 517 518 print('snapshots') 519 with O.table(GetRecountSnapshot.header, indent=True): 520 ncpus = unsigned(kern.globals.real_ncpus) 521 for i in range(ncpus): 522 snap = kern.PERCPU_GET('_snaps_percpu', i) 523 print(GetRecountSnapshot(i, snap, O=O)) 524