1# task-analyzer.py - comprehensive perf tasks analysis 2# SPDX-License-Identifier: GPL-2.0 3# Copyright (c) 2022, Hagen Paul Pfeifer <[email protected]> 4# Licensed under the terms of the GNU GPL License version 2 5# 6# Usage: 7# 8# perf record -e sched:sched_switch -a -- sleep 10 9# perf script report task-analyzer 10# 11 12from __future__ import print_function 13import sys 14import os 15import string 16import argparse 17import decimal 18 19 20sys.path.append( 21 os.environ["PERF_EXEC_PATH"] + "/scripts/python/Perf-Trace-Util/lib/Perf/Trace" 22) 23from perf_trace_context import * 24from Core import * 25 26# Definition of possible ASCII color codes 27_COLORS = { 28 "grey": "\033[90m", 29 "red": "\033[91m", 30 "green": "\033[92m", 31 "yellow": "\033[93m", 32 "blue": "\033[94m", 33 "violet": "\033[95m", 34 "reset": "\033[0m", 35} 36 37# Columns will have a static size to align everything properly 38# Support of 116 days of active update with nano precision 39LEN_SWITCHED_IN = len("9999999.999999999") # 17 40LEN_SWITCHED_OUT = len("9999999.999999999") # 17 41LEN_CPU = len("000") 42LEN_PID = len("maxvalue") # 8 43LEN_TID = len("maxvalue") # 8 44LEN_COMM = len("max-comms-length") # 16 45LEN_RUNTIME = len("999999.999") # 10 46# Support of 3.45 hours of timespans 47LEN_OUT_IN = len("99999999999.999") # 15 48LEN_OUT_OUT = len("99999999999.999") # 15 49LEN_IN_IN = len("99999999999.999") # 15 50LEN_IN_OUT = len("99999999999.999") # 15 51 52 53# py2/py3 compatibility layer, see PEP469 54try: 55 dict.iteritems 56except AttributeError: 57 # py3 58 def itervalues(d): 59 return iter(d.values()) 60 61 def iteritems(d): 62 return iter(d.items()) 63 64else: 65 # py2 66 def itervalues(d): 67 return d.itervalues() 68 69 def iteritems(d): 70 return d.iteritems() 71 72 73def _check_color(): 74 global _COLORS 75 """user enforced no-color or if stdout is no tty we disable colors""" 76 if sys.stdout.isatty() and args.stdio_color != "never": 77 return 78 _COLORS = { 79 "grey": "", 80 "red": "", 81 "green": "", 82 "yellow": "", 83 "blue": "", 84 "violet": "", 85 "reset": "", 86 } 87 88 89def _parse_args(): 90 global args 91 parser = argparse.ArgumentParser(description="Analyze tasks behavior") 92 parser.add_argument( 93 "--time-limit", 94 default=[], 95 help= 96 "print tasks only in time[s] window e.g" 97 " --time-limit 123.111:789.222(print all between 123.111 and 789.222)" 98 " --time-limit 123: (print all from 123)" 99 " --time-limit :456 (print all until incl. 456)", 100 ) 101 parser.add_argument( 102 "--summary", action="store_true", help="print addtional runtime information" 103 ) 104 parser.add_argument( 105 "--summary-only", action="store_true", help="print only summary without traces" 106 ) 107 parser.add_argument( 108 "--summary-extended", 109 action="store_true", 110 help="print the summary with additional information of max inter task times" 111 " relative to the prev task", 112 ) 113 parser.add_argument( 114 "--ns", action="store_true", help="show timestamps in nanoseconds" 115 ) 116 parser.add_argument( 117 "--ms", action="store_true", help="show timestamps in miliseconds" 118 ) 119 parser.add_argument( 120 "--extended-times", 121 action="store_true", 122 help="Show the elapsed times between schedule in/schedule out" 123 " of this task and the schedule in/schedule out of previous occurrence" 124 " of the same task", 125 ) 126 parser.add_argument( 127 "--filter-tasks", 128 default=[], 129 help="filter out unneeded tasks by tid, pid or processname." 130 " E.g --filter-task 1337,/sbin/init ", 131 ) 132 parser.add_argument( 133 "--limit-to-tasks", 134 default=[], 135 help="limit output to selected task by tid, pid, processname." 136 " E.g --limit-to-tasks 1337,/sbin/init", 137 ) 138 parser.add_argument( 139 "--highlight-tasks", 140 default="", 141 help="colorize special tasks by their pid/tid/comm." 142 " E.g. --highlight-tasks 1:red,mutt:yellow" 143 " Colors available: red,grey,yellow,blue,violet,green", 144 ) 145 parser.add_argument( 146 "--rename-comms-by-tids", 147 default="", 148 help="rename task names by using tid (<tid>:<newname>,<tid>:<newname>)" 149 " This option is handy for inexpressive processnames like python interpreted" 150 " process. E.g --rename 1337:my-python-app", 151 ) 152 parser.add_argument( 153 "--stdio-color", 154 default="auto", 155 choices=["always", "never", "auto"], 156 help="always, never or auto, allowing configuring color output" 157 " via the command line", 158 ) 159 args = parser.parse_args() 160 args.tid_renames = dict() 161 162 _argument_filter_sanity_check() 163 _argument_prepare_check() 164 165 166def time_uniter(unit): 167 picker = { 168 "s": 1, 169 "ms": 1e3, 170 "us": 1e6, 171 "ns": 1e9, 172 } 173 return picker[unit] 174 175 176def _init_db(): 177 global db 178 db = dict() 179 db["running"] = dict() 180 db["cpu"] = dict() 181 db["tid"] = dict() 182 db["global"] = [] 183 if args.summary or args.summary_extended or args.summary_only: 184 db["task_info"] = dict() 185 db["runtime_info"] = dict() 186 # min values for summary depending on the header 187 db["task_info"]["pid"] = len("PID") 188 db["task_info"]["tid"] = len("TID") 189 db["task_info"]["comm"] = len("Comm") 190 db["runtime_info"]["runs"] = len("Runs") 191 db["runtime_info"]["acc"] = len("Accumulated") 192 db["runtime_info"]["max"] = len("Max") 193 db["runtime_info"]["max_at"] = len("Max At") 194 db["runtime_info"]["min"] = len("Min") 195 db["runtime_info"]["mean"] = len("Mean") 196 db["runtime_info"]["median"] = len("Median") 197 if args.summary_extended: 198 db["inter_times"] = dict() 199 db["inter_times"]["out_in"] = len("Out-In") 200 db["inter_times"]["inter_at"] = len("At") 201 db["inter_times"]["out_out"] = len("Out-Out") 202 db["inter_times"]["in_in"] = len("In-In") 203 db["inter_times"]["in_out"] = len("In-Out") 204 205 206def _median(numbers): 207 """phython3 hat statistics module - we have nothing""" 208 n = len(numbers) 209 index = n // 2 210 if n % 2: 211 return sorted(numbers)[index] 212 return sum(sorted(numbers)[index - 1 : index + 1]) / 2 213 214 215def _mean(numbers): 216 return sum(numbers) / len(numbers) 217 218 219class Timespans(object): 220 """ 221 The elapsed time between two occurrences of the same task is being tracked with the 222 help of this class. There are 4 of those Timespans Out-Out, In-Out, Out-In and 223 In-In. 224 The first half of the name signals the first time point of the 225 first task. The second half of the name represents the second 226 timepoint of the second task. 227 """ 228 229 def __init__(self): 230 self._last_start = None 231 self._last_finish = None 232 self.out_out = -1 233 self.in_out = -1 234 self.out_in = -1 235 self.in_in = -1 236 if args.summary_extended: 237 self._time_in = -1 238 self.max_out_in = -1 239 self.max_at = -1 240 self.max_in_out = -1 241 self.max_in_in = -1 242 self.max_out_out = -1 243 244 def feed(self, task): 245 """ 246 Called for every recorded trace event to find process pair and calculate the 247 task timespans. Chronological ordering, feed does not do reordering 248 """ 249 if not self._last_finish: 250 self._last_start = task.time_in(time_unit) 251 self._last_finish = task.time_out(time_unit) 252 return 253 self._time_in = task.time_in() 254 time_in = task.time_in(time_unit) 255 time_out = task.time_out(time_unit) 256 self.in_in = time_in - self._last_start 257 self.out_in = time_in - self._last_finish 258 self.in_out = time_out - self._last_start 259 self.out_out = time_out - self._last_finish 260 if args.summary_extended: 261 self._update_max_entries() 262 self._last_finish = task.time_out(time_unit) 263 self._last_start = task.time_in(time_unit) 264 265 def _update_max_entries(self): 266 if self.in_in > self.max_in_in: 267 self.max_in_in = self.in_in 268 if self.out_out > self.max_out_out: 269 self.max_out_out = self.out_out 270 if self.in_out > self.max_in_out: 271 self.max_in_out = self.in_out 272 if self.out_in > self.max_out_in: 273 self.max_out_in = self.out_in 274 self.max_at = self._time_in 275 276 277 278 279class Summary(object): 280 """ 281 Primary instance for calculating the summary output. Processes the whole trace to 282 find and memorize relevant data such as mean, max et cetera. This instance handles 283 dynamic alignment aspects for summary output. 284 """ 285 286 def __init__(self): 287 self._body = [] 288 289 class AlignmentHelper: 290 """ 291 Used to calculated the alignment for the output of the summary. 292 """ 293 def __init__(self, pid, tid, comm, runs, acc, mean, 294 median, min, max, max_at): 295 self.pid = pid 296 self.tid = tid 297 self.comm = comm 298 self.runs = runs 299 self.acc = acc 300 self.mean = mean 301 self.median = median 302 self.min = min 303 self.max = max 304 self.max_at = max_at 305 if args.summary_extended: 306 self.out_in = None 307 self.inter_at = None 308 self.out_out = None 309 self.in_in = None 310 self.in_out = None 311 312 def _print_header(self): 313 ''' 314 Output is trimmed in _format_stats thus additional adjustment in the header 315 is needed, depending on the choice of timeunit. The adjustment corresponds 316 to the amount of column titles being adjusted in _column_titles. 317 ''' 318 decimal_precision = 6 if not args.ns else 9 319 fmt = " {{:^{}}}".format(sum(db["task_info"].values())) 320 fmt += " {{:^{}}}".format( 321 sum(db["runtime_info"].values()) - 2 * decimal_precision 322 ) 323 _header = ("Task Information", "Runtime Information") 324 325 if args.summary_extended: 326 fmt += " {{:^{}}}".format( 327 sum(db["inter_times"].values()) - 4 * decimal_precision 328 ) 329 _header += ("Max Inter Task Times",) 330 print(fmt.format(*_header)) 331 332 def _column_titles(self): 333 """ 334 Cells are being processed and displayed in different way so an alignment adjust 335 is implemented depeding on the choice of the timeunit. The positions of the max 336 values are being displayed in grey. Thus in their format two additional {}, 337 are placed for color set and reset. 338 """ 339 decimal_precision, time_precision = _prepare_fmt_precision() 340 fmt = " {{:>{}}}".format(db["task_info"]["pid"]) 341 fmt += " {{:>{}}}".format(db["task_info"]["tid"]) 342 fmt += " {{:>{}}}".format(db["task_info"]["comm"]) 343 fmt += " {{:>{}}}".format(db["runtime_info"]["runs"]) 344 fmt += " {{:>{}}}".format(db["runtime_info"]["acc"]) 345 fmt += " {{:>{}}}".format(db["runtime_info"]["mean"]) 346 fmt += " {{:>{}}}".format(db["runtime_info"]["median"]) 347 fmt += " {{:>{}}}".format(db["runtime_info"]["min"] - decimal_precision) 348 fmt += " {{:>{}}}".format(db["runtime_info"]["max"] - decimal_precision) 349 fmt += " {{}}{{:>{}}}{{}}".format(db["runtime_info"]["max_at"] - time_precision) 350 351 column_titles = ("PID", "TID", "Comm") 352 column_titles += ("Runs", "Accumulated", "Mean", "Median", "Min", "Max") 353 column_titles += (_COLORS["grey"], "At", _COLORS["reset"]) 354 355 if args.summary_extended: 356 fmt += " {{:>{}}}".format(db["inter_times"]["out_in"] - decimal_precision) 357 fmt += " {{}}{{:>{}}}{{}}".format( 358 db["inter_times"]["inter_at"] - time_precision 359 ) 360 fmt += " {{:>{}}}".format(db["inter_times"]["out_out"] - decimal_precision) 361 fmt += " {{:>{}}}".format(db["inter_times"]["in_in"] - decimal_precision) 362 fmt += " {{:>{}}}".format(db["inter_times"]["in_out"] - decimal_precision) 363 364 column_titles += ("Out-In", _COLORS["grey"], "Max At", _COLORS["reset"], 365 "Out-Out", "In-In", "In-Out") 366 print(fmt.format(*column_titles)) 367 368 def _task_stats(self): 369 """calculates the stats of every task and constructs the printable summary""" 370 for tid in sorted(db["tid"]): 371 color_one_sample = _COLORS["grey"] 372 color_reset = _COLORS["reset"] 373 no_executed = 0 374 runtimes = [] 375 time_in = [] 376 timespans = Timespans() 377 for task in db["tid"][tid]: 378 pid = task.pid 379 comm = task.comm 380 no_executed += 1 381 runtimes.append(task.runtime(time_unit)) 382 time_in.append(task.time_in()) 383 timespans.feed(task) 384 if len(runtimes) > 1: 385 color_one_sample = "" 386 color_reset = "" 387 time_max = max(runtimes) 388 time_min = min(runtimes) 389 max_at = time_in[runtimes.index(max(runtimes))] 390 391 # The size of the decimal after sum,mean and median varies, thus we cut 392 # the decimal number, by rounding it. It has no impact on the output, 393 # because we have a precision of the decimal points at the output. 394 time_sum = round(sum(runtimes), 3) 395 time_mean = round(_mean(runtimes), 3) 396 time_median = round(_median(runtimes), 3) 397 398 align_helper = self.AlignmentHelper(pid, tid, comm, no_executed, time_sum, 399 time_mean, time_median, time_min, time_max, max_at) 400 self._body.append([pid, tid, comm, no_executed, time_sum, color_one_sample, 401 time_mean, time_median, time_min, time_max, 402 _COLORS["grey"], max_at, _COLORS["reset"], color_reset]) 403 if args.summary_extended: 404 self._body[-1].extend([timespans.max_out_in, 405 _COLORS["grey"], timespans.max_at, 406 _COLORS["reset"], timespans.max_out_out, 407 timespans.max_in_in, 408 timespans.max_in_out]) 409 align_helper.out_in = timespans.max_out_in 410 align_helper.inter_at = timespans.max_at 411 align_helper.out_out = timespans.max_out_out 412 align_helper.in_in = timespans.max_in_in 413 align_helper.in_out = timespans.max_in_out 414 self._calc_alignments_summary(align_helper) 415 416 def _format_stats(self): 417 decimal_precision, time_precision = _prepare_fmt_precision() 418 fmt = " {{:>{}d}}".format(db["task_info"]["pid"]) 419 fmt += " {{:>{}d}}".format(db["task_info"]["tid"]) 420 fmt += " {{:>{}}}".format(db["task_info"]["comm"]) 421 fmt += " {{:>{}d}}".format(db["runtime_info"]["runs"]) 422 fmt += " {{:>{}.{}f}}".format(db["runtime_info"]["acc"], time_precision) 423 fmt += " {{}}{{:>{}.{}f}}".format(db["runtime_info"]["mean"], time_precision) 424 fmt += " {{:>{}.{}f}}".format(db["runtime_info"]["median"], time_precision) 425 fmt += " {{:>{}.{}f}}".format( 426 db["runtime_info"]["min"] - decimal_precision, time_precision 427 ) 428 fmt += " {{:>{}.{}f}}".format( 429 db["runtime_info"]["max"] - decimal_precision, time_precision 430 ) 431 fmt += " {{}}{{:>{}.{}f}}{{}}{{}}".format( 432 db["runtime_info"]["max_at"] - time_precision, decimal_precision 433 ) 434 if args.summary_extended: 435 fmt += " {{:>{}.{}f}}".format( 436 db["inter_times"]["out_in"] - decimal_precision, time_precision 437 ) 438 fmt += " {{}}{{:>{}.{}f}}{{}}".format( 439 db["inter_times"]["inter_at"] - time_precision, decimal_precision 440 ) 441 fmt += " {{:>{}.{}f}}".format( 442 db["inter_times"]["out_out"] - decimal_precision, time_precision 443 ) 444 fmt += " {{:>{}.{}f}}".format( 445 db["inter_times"]["in_in"] - decimal_precision, time_precision 446 ) 447 fmt += " {{:>{}.{}f}}".format( 448 db["inter_times"]["in_out"] - decimal_precision, time_precision 449 ) 450 return fmt 451 452 453 def _calc_alignments_summary(self, align_helper): 454 # Length is being cut in 3 groups so that further addition is easier to handle. 455 # The length of every argument from the alignment helper is being checked if it 456 # is longer than the longest until now. In that case the length is being saved. 457 for key in db["task_info"]: 458 if len(str(getattr(align_helper, key))) > db["task_info"][key]: 459 db["task_info"][key] = len(str(getattr(align_helper, key))) 460 for key in db["runtime_info"]: 461 if len(str(getattr(align_helper, key))) > db["runtime_info"][key]: 462 db["runtime_info"][key] = len(str(getattr(align_helper, key))) 463 if args.summary_extended: 464 for key in db["inter_times"]: 465 if len(str(getattr(align_helper, key))) > db["inter_times"][key]: 466 db["inter_times"][key] = len(str(getattr(align_helper, key))) 467 468 469 def print(self): 470 print("\nSummary") 471 self._task_stats() 472 self._print_header() 473 self._column_titles() 474 fmt = self._format_stats() 475 for i in range(len(self._body)): 476 print(fmt.format(*tuple(self._body[i]))) 477 478 479 480class Task(object): 481 """ The class is used to handle the information of a given task.""" 482 483 def __init__(self, id, tid, cpu, comm): 484 self.id = id 485 self.tid = tid 486 self.cpu = cpu 487 self.comm = comm 488 self.pid = None 489 self._time_in = None 490 self._time_out = None 491 492 def schedule_in_at(self, time): 493 """set the time where the task was scheduled in""" 494 self._time_in = time 495 496 def schedule_out_at(self, time): 497 """set the time where the task was scheduled out""" 498 self._time_out = time 499 500 def time_out(self, unit="s"): 501 """return time where a given task was scheduled out""" 502 factor = time_uniter(unit) 503 return self._time_out * decimal.Decimal(factor) 504 505 def time_in(self, unit="s"): 506 """return time where a given task was scheduled in""" 507 factor = time_uniter(unit) 508 return self._time_in * decimal.Decimal(factor) 509 510 def runtime(self, unit="us"): 511 factor = time_uniter(unit) 512 return (self._time_out - self._time_in) * decimal.Decimal(factor) 513 514 def update_pid(self, pid): 515 self.pid = pid 516 517 518def _task_id(pid, cpu): 519 """returns a "unique-enough" identifier, please do not change""" 520 return "{}-{}".format(pid, cpu) 521 522 523def _filter_non_printable(unfiltered): 524 """comm names may contain loony chars like '\x00000'""" 525 filtered = "" 526 for char in unfiltered: 527 if char not in string.printable: 528 continue 529 filtered += char 530 return filtered 531 532 533def _fmt_header(): 534 fmt = "{{:>{}}}".format(LEN_SWITCHED_IN) 535 fmt += " {{:>{}}}".format(LEN_SWITCHED_OUT) 536 fmt += " {{:>{}}}".format(LEN_CPU) 537 fmt += " {{:>{}}}".format(LEN_PID) 538 fmt += " {{:>{}}}".format(LEN_TID) 539 fmt += " {{:>{}}}".format(LEN_COMM) 540 fmt += " {{:>{}}}".format(LEN_RUNTIME) 541 fmt += " {{:>{}}}".format(LEN_OUT_IN) 542 if args.extended_times: 543 fmt += " {{:>{}}}".format(LEN_OUT_OUT) 544 fmt += " {{:>{}}}".format(LEN_IN_IN) 545 fmt += " {{:>{}}}".format(LEN_IN_OUT) 546 return fmt 547 548 549def _fmt_body(): 550 decimal_precision, time_precision = _prepare_fmt_precision() 551 fmt = "{{}}{{:{}.{}f}}".format(LEN_SWITCHED_IN, decimal_precision) 552 fmt += " {{:{}.{}f}}".format(LEN_SWITCHED_OUT, decimal_precision) 553 fmt += " {{:{}d}}".format(LEN_CPU) 554 fmt += " {{:{}d}}".format(LEN_PID) 555 fmt += " {{}}{{:{}d}}{{}}".format(LEN_TID) 556 fmt += " {{}}{{:>{}}}".format(LEN_COMM) 557 fmt += " {{:{}.{}f}}".format(LEN_RUNTIME, time_precision) 558 if args.extended_times: 559 fmt += " {{:{}.{}f}}".format(LEN_OUT_IN, time_precision) 560 fmt += " {{:{}.{}f}}".format(LEN_OUT_OUT, time_precision) 561 fmt += " {{:{}.{}f}}".format(LEN_IN_IN, time_precision) 562 fmt += " {{:{}.{}f}}{{}}".format(LEN_IN_OUT, time_precision) 563 else: 564 fmt += " {{:{}.{}f}}{{}}".format(LEN_OUT_IN, time_precision) 565 return fmt 566 567 568def _print_header(): 569 fmt = _fmt_header() 570 header = ("Switched-In", "Switched-Out", "CPU", "PID", "TID", "Comm", "Runtime", 571 "Time Out-In") 572 if args.extended_times: 573 header += ("Time Out-Out", "Time In-In", "Time In-Out") 574 print(fmt.format(*header)) 575 576 577def _print_task_finish(task): 578 """calculating every entry of a row and printing it immediately""" 579 c_row_set = "" 580 c_row_reset = "" 581 out_in = -1 582 out_out = -1 583 in_in = -1 584 in_out = -1 585 fmt = _fmt_body() 586 587 # depending on user provided highlight option we change the color 588 # for particular tasks 589 if str(task.tid) in args.highlight_tasks_map: 590 c_row_set = _COLORS[args.highlight_tasks_map[str(task.tid)]] 591 c_row_reset = _COLORS["reset"] 592 if task.comm in args.highlight_tasks_map: 593 c_row_set = _COLORS[args.highlight_tasks_map[task.comm]] 594 c_row_reset = _COLORS["reset"] 595 # grey-out entries if PID == TID, they 596 # are identical, no threaded model so the 597 # thread id (tid) do not matter 598 c_tid_set = "" 599 c_tid_reset = "" 600 if task.pid == task.tid: 601 c_tid_set = _COLORS["grey"] 602 c_tid_reset = _COLORS["reset"] 603 if task.tid in db["tid"]: 604 # get last task of tid 605 last_tid_task = db["tid"][task.tid][-1] 606 # feed the timespan calculate, last in tid db 607 # and second the current one 608 timespan_gap_tid = Timespans() 609 timespan_gap_tid.feed(last_tid_task) 610 timespan_gap_tid.feed(task) 611 out_in = timespan_gap_tid.out_in 612 out_out = timespan_gap_tid.out_out 613 in_in = timespan_gap_tid.in_in 614 in_out = timespan_gap_tid.in_out 615 if args.extended_times: 616 print(fmt.format(c_row_set, task.time_in(), task.time_out(), task.cpu, task.pid, 617 c_tid_set, task.tid, c_tid_reset, c_row_set, task.comm, 618 task.runtime(time_unit), out_in, out_out, in_in, in_out, 619 c_row_reset)) 620 else: 621 print(fmt.format(c_row_set, task.time_in(), task.time_out(), task.cpu, task.pid, 622 c_tid_set, task.tid, c_tid_reset, c_row_set, task.comm, 623 task.runtime(time_unit), out_in, c_row_reset)) 624 625 626def _record_cleanup(_list): 627 """ 628 no need to store more then one element if --summarize 629 is not enabled 630 """ 631 if not args.summary and len(_list) > 1: 632 _list = _list[len(_list) - 1 :] 633 634 635def _record_by_tid(task): 636 tid = task.tid 637 if tid not in db["tid"]: 638 db["tid"][tid] = [] 639 db["tid"][tid].append(task) 640 _record_cleanup(db["tid"][tid]) 641 642 643def _record_by_cpu(task): 644 cpu = task.cpu 645 if cpu not in db["cpu"]: 646 db["cpu"][cpu] = [] 647 db["cpu"][cpu].append(task) 648 _record_cleanup(db["cpu"][cpu]) 649 650 651def _record_global(task): 652 """record all executed task, ordered by finish chronological""" 653 db["global"].append(task) 654 _record_cleanup(db["global"]) 655 656 657def _handle_task_finish(tid, cpu, time, perf_sample_dict): 658 if tid == 0: 659 return 660 _id = _task_id(tid, cpu) 661 if _id not in db["running"]: 662 # may happen, if we missed the switch to 663 # event. Seen in combination with --exclude-perf 664 # where the start is filtered out, but not the 665 # switched in. Probably a bug in exclude-perf 666 # option. 667 return 668 task = db["running"][_id] 669 task.schedule_out_at(time) 670 671 # record tid, during schedule in the tid 672 # is not available, update now 673 pid = int(perf_sample_dict["sample"]["pid"]) 674 675 task.update_pid(pid) 676 del db["running"][_id] 677 678 # print only tasks which are not being filtered and no print of trace 679 # for summary only, but record every task. 680 if not _limit_filtered(tid, pid, task.comm) and not args.summary_only: 681 _print_task_finish(task) 682 _record_by_tid(task) 683 _record_by_cpu(task) 684 _record_global(task) 685 686 687def _handle_task_start(tid, cpu, comm, time): 688 if tid == 0: 689 return 690 if tid in args.tid_renames: 691 comm = args.tid_renames[tid] 692 _id = _task_id(tid, cpu) 693 if _id in db["running"]: 694 # handle corner cases where already running tasks 695 # are switched-to again - saw this via --exclude-perf 696 # recorded traces. We simple ignore this "second start" 697 # event. 698 return 699 assert _id not in db["running"] 700 task = Task(_id, tid, cpu, comm) 701 task.schedule_in_at(time) 702 db["running"][_id] = task 703 704 705def _time_to_internal(time_ns): 706 """ 707 To prevent float rounding errors we use Decimal internally 708 """ 709 return decimal.Decimal(time_ns) / decimal.Decimal(1e9) 710 711 712def _limit_filtered(tid, pid, comm): 713 if args.filter_tasks: 714 if str(tid) in args.filter_tasks or comm in args.filter_tasks: 715 return True 716 else: 717 return False 718 if args.limit_to_tasks: 719 if str(tid) in args.limit_to_tasks or comm in args.limit_to_tasks: 720 return False 721 else: 722 return True 723 724 725def _argument_filter_sanity_check(): 726 if args.limit_to_tasks and args.filter_tasks: 727 sys.exit("Error: Filter and Limit at the same time active.") 728 if args.extended_times and args.summary_only: 729 sys.exit("Error: Summary only and extended times active.") 730 if args.time_limit and ":" not in args.time_limit: 731 sys.exit( 732 "Error: No bound set for time limit. Please set bound by ':' e.g :123." 733 ) 734 if args.time_limit and (args.summary or args.summary_only or args.summary_extended): 735 sys.exit("Error: Cannot set time limit and print summary") 736 737 738def _argument_prepare_check(): 739 global time_unit 740 if args.filter_tasks: 741 args.filter_tasks = args.filter_tasks.split(",") 742 if args.limit_to_tasks: 743 args.limit_to_tasks = args.limit_to_tasks.split(",") 744 if args.time_limit: 745 args.time_limit = args.time_limit.split(":") 746 for rename_tuple in args.rename_comms_by_tids.split(","): 747 tid_name = rename_tuple.split(":") 748 if len(tid_name) != 2: 749 continue 750 args.tid_renames[int(tid_name[0])] = tid_name[1] 751 args.highlight_tasks_map = dict() 752 for highlight_tasks_tuple in args.highlight_tasks.split(","): 753 tasks_color_map = highlight_tasks_tuple.split(":") 754 # default highlight color to red if no color set by user 755 if len(tasks_color_map) == 1: 756 tasks_color_map.append("red") 757 if args.highlight_tasks and tasks_color_map[1].lower() not in _COLORS: 758 sys.exit( 759 "Error: Color not defined, please choose from grey,red,green,yellow,blue," 760 "violet" 761 ) 762 if len(tasks_color_map) != 2: 763 continue 764 args.highlight_tasks_map[tasks_color_map[0]] = tasks_color_map[1] 765 time_unit = "us" 766 if args.ns: 767 time_unit = "ns" 768 elif args.ms: 769 time_unit = "ms" 770 771 772def _is_within_timelimit(time): 773 """ 774 Check if a time limit was given by parameter, if so ignore the rest. If not, 775 process the recorded trace in its entirety. 776 """ 777 if not args.time_limit: 778 return True 779 lower_time_limit = args.time_limit[0] 780 upper_time_limit = args.time_limit[1] 781 # check for upper limit 782 if upper_time_limit == "": 783 if time >= decimal.Decimal(lower_time_limit): 784 return True 785 # check for lower limit 786 if lower_time_limit == "": 787 if time <= decimal.Decimal(upper_time_limit): 788 return True 789 # quit if time exceeds upper limit. Good for big datasets 790 else: 791 quit() 792 if lower_time_limit != "" and upper_time_limit != "": 793 if (time >= decimal.Decimal(lower_time_limit) and 794 time <= decimal.Decimal(upper_time_limit)): 795 return True 796 # quit if time exceeds upper limit. Good for big datasets 797 elif time > decimal.Decimal(upper_time_limit): 798 quit() 799 800def _prepare_fmt_precision(): 801 decimal_precision = 6 802 time_precision = 3 803 if args.ns: 804 decimal_precision = 9 805 time_precision = 0 806 return decimal_precision, time_precision 807 808 809def trace_unhandled(event_name, context, event_fields_dict, perf_sample_dict): 810 pass 811 812 813def trace_begin(): 814 _parse_args() 815 _check_color() 816 _init_db() 817 if not args.summary_only: 818 _print_header() 819 820def trace_end(): 821 if args.summary or args.summary_extended or args.summary_only: 822 Summary().print() 823 824def sched__sched_switch(event_name, context, common_cpu, common_secs, common_nsecs, 825 common_pid, common_comm, common_callchain, prev_comm, 826 prev_pid, prev_prio, prev_state, next_comm, next_pid, 827 next_prio, perf_sample_dict): 828 # ignore common_secs & common_nsecs cause we need 829 # high res timestamp anyway, using the raw value is 830 # faster 831 time = _time_to_internal(perf_sample_dict["sample"]["time"]) 832 if not _is_within_timelimit(time): 833 # user specific --time-limit a:b set 834 return 835 836 next_comm = _filter_non_printable(next_comm) 837 _handle_task_finish(prev_pid, common_cpu, time, perf_sample_dict) 838 _handle_task_start(next_pid, common_cpu, next_comm, time) 839