935 lines · python
1# task-analyzer.py - comprehensive perf tasks analysis2# SPDX-License-Identifier: GPL-2.03# Copyright (c) 2022, Hagen Paul Pfeifer <hagen@jauu.net>4# Licensed under the terms of the GNU GPL License version 25#6# Usage:7#8# perf record -e sched:sched_switch -a -- sleep 109# perf script report task-analyzer10#11 12from __future__ import print_function13import sys14import os15import string16import argparse17import decimal18 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 codes27_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 properly38# Support of 116 days of active update with nano precision39LEN_SWITCHED_IN = len("9999999.999999999") # 1740LEN_SWITCHED_OUT = len("9999999.999999999") # 1741LEN_CPU = len("000")42LEN_PID = len("maxvalue") # 843LEN_TID = len("maxvalue") # 844LEN_COMM = len("max-comms-length") # 1645LEN_RUNTIME = len("999999.999") # 1046# Support of 3.45 hours of timespans47LEN_OUT_IN = len("99999999999.999") # 1548LEN_OUT_OUT = len("99999999999.999") # 1549LEN_IN_IN = len("99999999999.999") # 1550LEN_IN_OUT = len("99999999999.999") # 1551 52 53# py2/py3 compatibility layer, see PEP46954try:55 dict.iteritems56except AttributeError:57 # py358 def itervalues(d):59 return iter(d.values())60 61 def iteritems(d):62 return iter(d.items())63 64else:65 # py266 def itervalues(d):67 return d.itervalues()68 69 def iteritems(d):70 return d.iteritems()71 72 73def _check_color():74 global _COLORS75 """user enforced no-color or if stdout is no tty we disable colors"""76 if sys.stdout.isatty() and args.stdio_color != "never":77 return78 _COLORS = {79 "grey": "",80 "red": "",81 "green": "",82 "yellow": "",83 "blue": "",84 "violet": "",85 "reset": "",86 }87 88 89def _parse_args():90 global args91 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 milliseconds"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 parser.add_argument(160 "--csv",161 default="",162 help="Write trace to file selected by user. Options, like --ns or --extended"163 "-times are used.",164 )165 parser.add_argument(166 "--csv-summary",167 default="",168 help="Write summary to file selected by user. Options, like --ns or"169 " --summary-extended are used.",170 )171 args = parser.parse_args()172 args.tid_renames = dict()173 174 _argument_filter_sanity_check()175 _argument_prepare_check()176 177 178def time_uniter(unit):179 picker = {180 "s": 1,181 "ms": 1e3,182 "us": 1e6,183 "ns": 1e9,184 }185 return picker[unit]186 187 188def _init_db():189 global db190 db = dict()191 db["running"] = dict()192 db["cpu"] = dict()193 db["tid"] = dict()194 db["global"] = []195 if args.summary or args.summary_extended or args.summary_only:196 db["task_info"] = dict()197 db["runtime_info"] = dict()198 # min values for summary depending on the header199 db["task_info"]["pid"] = len("PID")200 db["task_info"]["tid"] = len("TID")201 db["task_info"]["comm"] = len("Comm")202 db["runtime_info"]["runs"] = len("Runs")203 db["runtime_info"]["acc"] = len("Accumulated")204 db["runtime_info"]["max"] = len("Max")205 db["runtime_info"]["max_at"] = len("Max At")206 db["runtime_info"]["min"] = len("Min")207 db["runtime_info"]["mean"] = len("Mean")208 db["runtime_info"]["median"] = len("Median")209 if args.summary_extended:210 db["inter_times"] = dict()211 db["inter_times"]["out_in"] = len("Out-In")212 db["inter_times"]["inter_at"] = len("At")213 db["inter_times"]["out_out"] = len("Out-Out")214 db["inter_times"]["in_in"] = len("In-In")215 db["inter_times"]["in_out"] = len("In-Out")216 217 218def _median(numbers):219 """phython3 hat statistics module - we have nothing"""220 n = len(numbers)221 index = n // 2222 if n % 2:223 return sorted(numbers)[index]224 return sum(sorted(numbers)[index - 1 : index + 1]) / 2225 226 227def _mean(numbers):228 return sum(numbers) / len(numbers)229 230 231class Timespans(object):232 """233 The elapsed time between two occurrences of the same task is being tracked with the234 help of this class. There are 4 of those Timespans Out-Out, In-Out, Out-In and235 In-In.236 The first half of the name signals the first time point of the237 first task. The second half of the name represents the second238 timepoint of the second task.239 """240 241 def __init__(self):242 self._last_start = None243 self._last_finish = None244 self.out_out = -1245 self.in_out = -1246 self.out_in = -1247 self.in_in = -1248 if args.summary_extended:249 self._time_in = -1250 self.max_out_in = -1251 self.max_at = -1252 self.max_in_out = -1253 self.max_in_in = -1254 self.max_out_out = -1255 256 def feed(self, task):257 """258 Called for every recorded trace event to find process pair and calculate the259 task timespans. Chronological ordering, feed does not do reordering260 """261 if not self._last_finish:262 self._last_start = task.time_in(time_unit)263 self._last_finish = task.time_out(time_unit)264 return265 self._time_in = task.time_in()266 time_in = task.time_in(time_unit)267 time_out = task.time_out(time_unit)268 self.in_in = time_in - self._last_start269 self.out_in = time_in - self._last_finish270 self.in_out = time_out - self._last_start271 self.out_out = time_out - self._last_finish272 if args.summary_extended:273 self._update_max_entries()274 self._last_finish = task.time_out(time_unit)275 self._last_start = task.time_in(time_unit)276 277 def _update_max_entries(self):278 if self.in_in > self.max_in_in:279 self.max_in_in = self.in_in280 if self.out_out > self.max_out_out:281 self.max_out_out = self.out_out282 if self.in_out > self.max_in_out:283 self.max_in_out = self.in_out284 if self.out_in > self.max_out_in:285 self.max_out_in = self.out_in286 self.max_at = self._time_in287 288 289 290class Summary(object):291 """292 Primary instance for calculating the summary output. Processes the whole trace to293 find and memorize relevant data such as mean, max et cetera. This instance handles294 dynamic alignment aspects for summary output.295 """296 297 def __init__(self):298 self._body = []299 300 class AlignmentHelper:301 """302 Used to calculated the alignment for the output of the summary.303 """304 def __init__(self, pid, tid, comm, runs, acc, mean,305 median, min, max, max_at):306 self.pid = pid307 self.tid = tid308 self.comm = comm309 self.runs = runs310 self.acc = acc311 self.mean = mean312 self.median = median313 self.min = min314 self.max = max315 self.max_at = max_at316 if args.summary_extended:317 self.out_in = None318 self.inter_at = None319 self.out_out = None320 self.in_in = None321 self.in_out = None322 323 def _print_header(self):324 '''325 Output is trimmed in _format_stats thus additional adjustment in the header326 is needed, depending on the choice of timeunit. The adjustment corresponds327 to the amount of column titles being adjusted in _column_titles.328 '''329 decimal_precision = 6 if not args.ns else 9330 fmt = " {{:^{}}}".format(sum(db["task_info"].values()))331 fmt += " {{:^{}}}".format(332 sum(db["runtime_info"].values()) - 2 * decimal_precision333 )334 _header = ("Task Information", "Runtime Information")335 336 if args.summary_extended:337 fmt += " {{:^{}}}".format(338 sum(db["inter_times"].values()) - 4 * decimal_precision339 )340 _header += ("Max Inter Task Times",)341 fd_sum.write(fmt.format(*_header) + "\n")342 343 def _column_titles(self):344 """345 Cells are being processed and displayed in different way so an alignment adjust346 is implemented depeding on the choice of the timeunit. The positions of the max347 values are being displayed in grey. Thus in their format two additional {},348 are placed for color set and reset.349 """350 separator, fix_csv_align = _prepare_fmt_sep()351 decimal_precision, time_precision = _prepare_fmt_precision()352 fmt = "{{:>{}}}".format(db["task_info"]["pid"] * fix_csv_align)353 fmt += "{}{{:>{}}}".format(separator, db["task_info"]["tid"] * fix_csv_align)354 fmt += "{}{{:>{}}}".format(separator, db["task_info"]["comm"] * fix_csv_align)355 fmt += "{}{{:>{}}}".format(separator, db["runtime_info"]["runs"] * fix_csv_align)356 fmt += "{}{{:>{}}}".format(separator, db["runtime_info"]["acc"] * fix_csv_align)357 fmt += "{}{{:>{}}}".format(separator, db["runtime_info"]["mean"] * fix_csv_align)358 fmt += "{}{{:>{}}}".format(359 separator, db["runtime_info"]["median"] * fix_csv_align360 )361 fmt += "{}{{:>{}}}".format(362 separator, (db["runtime_info"]["min"] - decimal_precision) * fix_csv_align363 )364 fmt += "{}{{:>{}}}".format(365 separator, (db["runtime_info"]["max"] - decimal_precision) * fix_csv_align366 )367 fmt += "{}{{}}{{:>{}}}{{}}".format(368 separator, (db["runtime_info"]["max_at"] - time_precision) * fix_csv_align369 )370 371 column_titles = ("PID", "TID", "Comm")372 column_titles += ("Runs", "Accumulated", "Mean", "Median", "Min", "Max")373 column_titles += (_COLORS["grey"], "Max At", _COLORS["reset"])374 375 if args.summary_extended:376 fmt += "{}{{:>{}}}".format(377 separator,378 (db["inter_times"]["out_in"] - decimal_precision) * fix_csv_align379 )380 fmt += "{}{{}}{{:>{}}}{{}}".format(381 separator,382 (db["inter_times"]["inter_at"] - time_precision) * fix_csv_align383 )384 fmt += "{}{{:>{}}}".format(385 separator,386 (db["inter_times"]["out_out"] - decimal_precision) * fix_csv_align387 )388 fmt += "{}{{:>{}}}".format(389 separator,390 (db["inter_times"]["in_in"] - decimal_precision) * fix_csv_align391 )392 fmt += "{}{{:>{}}}".format(393 separator,394 (db["inter_times"]["in_out"] - decimal_precision) * fix_csv_align395 )396 397 column_titles += ("Out-In", _COLORS["grey"], "Max At", _COLORS["reset"],398 "Out-Out", "In-In", "In-Out")399 400 fd_sum.write(fmt.format(*column_titles) + "\n")401 402 403 def _task_stats(self):404 """calculates the stats of every task and constructs the printable summary"""405 for tid in sorted(db["tid"]):406 color_one_sample = _COLORS["grey"]407 color_reset = _COLORS["reset"]408 no_executed = 0409 runtimes = []410 time_in = []411 timespans = Timespans()412 for task in db["tid"][tid]:413 pid = task.pid414 comm = task.comm415 no_executed += 1416 runtimes.append(task.runtime(time_unit))417 time_in.append(task.time_in())418 timespans.feed(task)419 if len(runtimes) > 1:420 color_one_sample = ""421 color_reset = ""422 time_max = max(runtimes)423 time_min = min(runtimes)424 max_at = time_in[runtimes.index(max(runtimes))]425 426 # The size of the decimal after sum,mean and median varies, thus we cut427 # the decimal number, by rounding it. It has no impact on the output,428 # because we have a precision of the decimal points at the output.429 time_sum = round(sum(runtimes), 3)430 time_mean = round(_mean(runtimes), 3)431 time_median = round(_median(runtimes), 3)432 433 align_helper = self.AlignmentHelper(pid, tid, comm, no_executed, time_sum,434 time_mean, time_median, time_min, time_max, max_at)435 self._body.append([pid, tid, comm, no_executed, time_sum, color_one_sample,436 time_mean, time_median, time_min, time_max,437 _COLORS["grey"], max_at, _COLORS["reset"], color_reset])438 if args.summary_extended:439 self._body[-1].extend([timespans.max_out_in,440 _COLORS["grey"], timespans.max_at,441 _COLORS["reset"], timespans.max_out_out,442 timespans.max_in_in,443 timespans.max_in_out])444 align_helper.out_in = timespans.max_out_in445 align_helper.inter_at = timespans.max_at446 align_helper.out_out = timespans.max_out_out447 align_helper.in_in = timespans.max_in_in448 align_helper.in_out = timespans.max_in_out449 self._calc_alignments_summary(align_helper)450 451 def _format_stats(self):452 separator, fix_csv_align = _prepare_fmt_sep()453 decimal_precision, time_precision = _prepare_fmt_precision()454 len_pid = db["task_info"]["pid"] * fix_csv_align455 len_tid = db["task_info"]["tid"] * fix_csv_align456 len_comm = db["task_info"]["comm"] * fix_csv_align457 len_runs = db["runtime_info"]["runs"] * fix_csv_align458 len_acc = db["runtime_info"]["acc"] * fix_csv_align459 len_mean = db["runtime_info"]["mean"] * fix_csv_align460 len_median = db["runtime_info"]["median"] * fix_csv_align461 len_min = (db["runtime_info"]["min"] - decimal_precision) * fix_csv_align462 len_max = (db["runtime_info"]["max"] - decimal_precision) * fix_csv_align463 len_max_at = (db["runtime_info"]["max_at"] - time_precision) * fix_csv_align464 if args.summary_extended:465 len_out_in = (466 db["inter_times"]["out_in"] - decimal_precision467 ) * fix_csv_align468 len_inter_at = (469 db["inter_times"]["inter_at"] - time_precision470 ) * fix_csv_align471 len_out_out = (472 db["inter_times"]["out_out"] - decimal_precision473 ) * fix_csv_align474 len_in_in = (db["inter_times"]["in_in"] - decimal_precision) * fix_csv_align475 len_in_out = (476 db["inter_times"]["in_out"] - decimal_precision477 ) * fix_csv_align478 479 fmt = "{{:{}d}}".format(len_pid)480 fmt += "{}{{:{}d}}".format(separator, len_tid)481 fmt += "{}{{:>{}}}".format(separator, len_comm)482 fmt += "{}{{:{}d}}".format(separator, len_runs)483 fmt += "{}{{:{}.{}f}}".format(separator, len_acc, time_precision)484 fmt += "{}{{}}{{:{}.{}f}}".format(separator, len_mean, time_precision)485 fmt += "{}{{:{}.{}f}}".format(separator, len_median, time_precision)486 fmt += "{}{{:{}.{}f}}".format(separator, len_min, time_precision)487 fmt += "{}{{:{}.{}f}}".format(separator, len_max, time_precision)488 fmt += "{}{{}}{{:{}.{}f}}{{}}{{}}".format(489 separator, len_max_at, decimal_precision490 )491 if args.summary_extended:492 fmt += "{}{{:{}.{}f}}".format(separator, len_out_in, time_precision)493 fmt += "{}{{}}{{:{}.{}f}}{{}}".format(494 separator, len_inter_at, decimal_precision495 )496 fmt += "{}{{:{}.{}f}}".format(separator, len_out_out, time_precision)497 fmt += "{}{{:{}.{}f}}".format(separator, len_in_in, time_precision)498 fmt += "{}{{:{}.{}f}}".format(separator, len_in_out, time_precision)499 return fmt500 501 502 def _calc_alignments_summary(self, align_helper):503 # Length is being cut in 3 groups so that further addition is easier to handle.504 # The length of every argument from the alignment helper is being checked if it505 # is longer than the longest until now. In that case the length is being saved.506 for key in db["task_info"]:507 if len(str(getattr(align_helper, key))) > db["task_info"][key]:508 db["task_info"][key] = len(str(getattr(align_helper, key)))509 for key in db["runtime_info"]:510 if len(str(getattr(align_helper, key))) > db["runtime_info"][key]:511 db["runtime_info"][key] = len(str(getattr(align_helper, key)))512 if args.summary_extended:513 for key in db["inter_times"]:514 if len(str(getattr(align_helper, key))) > db["inter_times"][key]:515 db["inter_times"][key] = len(str(getattr(align_helper, key)))516 517 518 def print(self):519 self._task_stats()520 fmt = self._format_stats()521 522 if not args.csv_summary:523 print("\nSummary")524 self._print_header()525 self._column_titles()526 for i in range(len(self._body)):527 fd_sum.write(fmt.format(*tuple(self._body[i])) + "\n")528 529 530 531class Task(object):532 """ The class is used to handle the information of a given task."""533 534 def __init__(self, id, tid, cpu, comm):535 self.id = id536 self.tid = tid537 self.cpu = cpu538 self.comm = comm539 self.pid = None540 self._time_in = None541 self._time_out = None542 543 def schedule_in_at(self, time):544 """set the time where the task was scheduled in"""545 self._time_in = time546 547 def schedule_out_at(self, time):548 """set the time where the task was scheduled out"""549 self._time_out = time550 551 def time_out(self, unit="s"):552 """return time where a given task was scheduled out"""553 factor = time_uniter(unit)554 return self._time_out * decimal.Decimal(factor)555 556 def time_in(self, unit="s"):557 """return time where a given task was scheduled in"""558 factor = time_uniter(unit)559 return self._time_in * decimal.Decimal(factor)560 561 def runtime(self, unit="us"):562 factor = time_uniter(unit)563 return (self._time_out - self._time_in) * decimal.Decimal(factor)564 565 def update_pid(self, pid):566 self.pid = pid567 568 569def _task_id(pid, cpu):570 """returns a "unique-enough" identifier, please do not change"""571 return "{}-{}".format(pid, cpu)572 573 574def _filter_non_printable(unfiltered):575 """comm names may contain loony chars like '\x00000'"""576 filtered = ""577 for char in unfiltered:578 if char not in string.printable:579 continue580 filtered += char581 return filtered582 583 584def _fmt_header():585 separator, fix_csv_align = _prepare_fmt_sep()586 fmt = "{{:>{}}}".format(LEN_SWITCHED_IN*fix_csv_align)587 fmt += "{}{{:>{}}}".format(separator, LEN_SWITCHED_OUT*fix_csv_align)588 fmt += "{}{{:>{}}}".format(separator, LEN_CPU*fix_csv_align)589 fmt += "{}{{:>{}}}".format(separator, LEN_PID*fix_csv_align)590 fmt += "{}{{:>{}}}".format(separator, LEN_TID*fix_csv_align)591 fmt += "{}{{:>{}}}".format(separator, LEN_COMM*fix_csv_align)592 fmt += "{}{{:>{}}}".format(separator, LEN_RUNTIME*fix_csv_align)593 fmt += "{}{{:>{}}}".format(separator, LEN_OUT_IN*fix_csv_align)594 if args.extended_times:595 fmt += "{}{{:>{}}}".format(separator, LEN_OUT_OUT*fix_csv_align)596 fmt += "{}{{:>{}}}".format(separator, LEN_IN_IN*fix_csv_align)597 fmt += "{}{{:>{}}}".format(separator, LEN_IN_OUT*fix_csv_align)598 return fmt599 600 601def _fmt_body():602 separator, fix_csv_align = _prepare_fmt_sep()603 decimal_precision, time_precision = _prepare_fmt_precision()604 fmt = "{{}}{{:{}.{}f}}".format(LEN_SWITCHED_IN*fix_csv_align, decimal_precision)605 fmt += "{}{{:{}.{}f}}".format(606 separator, LEN_SWITCHED_OUT*fix_csv_align, decimal_precision607 )608 fmt += "{}{{:{}d}}".format(separator, LEN_CPU*fix_csv_align)609 fmt += "{}{{:{}d}}".format(separator, LEN_PID*fix_csv_align)610 fmt += "{}{{}}{{:{}d}}{{}}".format(separator, LEN_TID*fix_csv_align)611 fmt += "{}{{}}{{:>{}}}".format(separator, LEN_COMM*fix_csv_align)612 fmt += "{}{{:{}.{}f}}".format(separator, LEN_RUNTIME*fix_csv_align, time_precision)613 if args.extended_times:614 fmt += "{}{{:{}.{}f}}".format(separator, LEN_OUT_IN*fix_csv_align, time_precision)615 fmt += "{}{{:{}.{}f}}".format(separator, LEN_OUT_OUT*fix_csv_align, time_precision)616 fmt += "{}{{:{}.{}f}}".format(separator, LEN_IN_IN*fix_csv_align, time_precision)617 fmt += "{}{{:{}.{}f}}{{}}".format(618 separator, LEN_IN_OUT*fix_csv_align, time_precision619 )620 else:621 fmt += "{}{{:{}.{}f}}{{}}".format(622 separator, LEN_OUT_IN*fix_csv_align, time_precision623 )624 return fmt625 626 627def _print_header():628 fmt = _fmt_header()629 header = ("Switched-In", "Switched-Out", "CPU", "PID", "TID", "Comm", "Runtime",630 "Time Out-In")631 if args.extended_times:632 header += ("Time Out-Out", "Time In-In", "Time In-Out")633 fd_task.write(fmt.format(*header) + "\n")634 635 636 637def _print_task_finish(task):638 """calculating every entry of a row and printing it immediately"""639 c_row_set = ""640 c_row_reset = ""641 out_in = -1642 out_out = -1643 in_in = -1644 in_out = -1645 fmt = _fmt_body()646 # depending on user provided highlight option we change the color647 # for particular tasks648 if str(task.tid) in args.highlight_tasks_map:649 c_row_set = _COLORS[args.highlight_tasks_map[str(task.tid)]]650 c_row_reset = _COLORS["reset"]651 if task.comm in args.highlight_tasks_map:652 c_row_set = _COLORS[args.highlight_tasks_map[task.comm]]653 c_row_reset = _COLORS["reset"]654 # grey-out entries if PID == TID, they655 # are identical, no threaded model so the656 # thread id (tid) do not matter657 c_tid_set = ""658 c_tid_reset = ""659 if task.pid == task.tid:660 c_tid_set = _COLORS["grey"]661 c_tid_reset = _COLORS["reset"]662 if task.tid in db["tid"]:663 # get last task of tid664 last_tid_task = db["tid"][task.tid][-1]665 # feed the timespan calculate, last in tid db666 # and second the current one667 timespan_gap_tid = Timespans()668 timespan_gap_tid.feed(last_tid_task)669 timespan_gap_tid.feed(task)670 out_in = timespan_gap_tid.out_in671 out_out = timespan_gap_tid.out_out672 in_in = timespan_gap_tid.in_in673 in_out = timespan_gap_tid.in_out674 675 676 if args.extended_times:677 line_out = fmt.format(c_row_set, task.time_in(), task.time_out(), task.cpu,678 task.pid, c_tid_set, task.tid, c_tid_reset, c_row_set, task.comm,679 task.runtime(time_unit), out_in, out_out, in_in, in_out,680 c_row_reset) + "\n"681 else:682 line_out = fmt.format(c_row_set, task.time_in(), task.time_out(), task.cpu,683 task.pid, c_tid_set, task.tid, c_tid_reset, c_row_set, task.comm,684 task.runtime(time_unit), out_in, c_row_reset) + "\n"685 try:686 fd_task.write(line_out)687 except(IOError):688 # don't mangle the output if user SIGINT this script689 sys.exit()690 691def _record_cleanup(_list):692 """693 no need to store more then one element if --summarize694 is not enabled695 """696 if not args.summary and len(_list) > 1:697 _list = _list[len(_list) - 1 :]698 699 700def _record_by_tid(task):701 tid = task.tid702 if tid not in db["tid"]:703 db["tid"][tid] = []704 db["tid"][tid].append(task)705 _record_cleanup(db["tid"][tid])706 707 708def _record_by_cpu(task):709 cpu = task.cpu710 if cpu not in db["cpu"]:711 db["cpu"][cpu] = []712 db["cpu"][cpu].append(task)713 _record_cleanup(db["cpu"][cpu])714 715 716def _record_global(task):717 """record all executed task, ordered by finish chronological"""718 db["global"].append(task)719 _record_cleanup(db["global"])720 721 722def _handle_task_finish(tid, cpu, time, perf_sample_dict):723 if tid == 0:724 return725 _id = _task_id(tid, cpu)726 if _id not in db["running"]:727 # may happen, if we missed the switch to728 # event. Seen in combination with --exclude-perf729 # where the start is filtered out, but not the730 # switched in. Probably a bug in exclude-perf731 # option.732 return733 task = db["running"][_id]734 task.schedule_out_at(time)735 736 # record tid, during schedule in the tid737 # is not available, update now738 pid = int(perf_sample_dict["sample"]["pid"])739 740 task.update_pid(pid)741 del db["running"][_id]742 743 # print only tasks which are not being filtered and no print of trace744 # for summary only, but record every task.745 if not _limit_filtered(tid, pid, task.comm) and not args.summary_only:746 _print_task_finish(task)747 _record_by_tid(task)748 _record_by_cpu(task)749 _record_global(task)750 751 752def _handle_task_start(tid, cpu, comm, time):753 if tid == 0:754 return755 if tid in args.tid_renames:756 comm = args.tid_renames[tid]757 _id = _task_id(tid, cpu)758 if _id in db["running"]:759 # handle corner cases where already running tasks760 # are switched-to again - saw this via --exclude-perf761 # recorded traces. We simple ignore this "second start"762 # event.763 return764 assert _id not in db["running"]765 task = Task(_id, tid, cpu, comm)766 task.schedule_in_at(time)767 db["running"][_id] = task768 769 770def _time_to_internal(time_ns):771 """772 To prevent float rounding errors we use Decimal internally773 """774 return decimal.Decimal(time_ns) / decimal.Decimal(1e9)775 776 777def _limit_filtered(tid, pid, comm):778 if args.filter_tasks:779 if str(tid) in args.filter_tasks or comm in args.filter_tasks:780 return True781 else:782 return False783 if args.limit_to_tasks:784 if str(tid) in args.limit_to_tasks or comm in args.limit_to_tasks:785 return False786 else:787 return True788 789 790def _argument_filter_sanity_check():791 if args.limit_to_tasks and args.filter_tasks:792 sys.exit("Error: Filter and Limit at the same time active.")793 if args.extended_times and args.summary_only:794 sys.exit("Error: Summary only and extended times active.")795 if args.time_limit and ":" not in args.time_limit:796 sys.exit(797 "Error: No bound set for time limit. Please set bound by ':' e.g :123."798 )799 if args.time_limit and (args.summary or args.summary_only or args.summary_extended):800 sys.exit("Error: Cannot set time limit and print summary")801 if args.csv_summary:802 args.summary = True803 if args.csv == args.csv_summary:804 sys.exit("Error: Chosen files for csv and csv summary are the same")805 if args.csv and (args.summary_extended or args.summary) and not args.csv_summary:806 sys.exit("Error: No file chosen to write summary to. Choose with --csv-summary "807 "<file>")808 if args.csv and args.summary_only:809 sys.exit("Error: --csv chosen and --summary-only. Standard task would not be"810 "written to csv file.")811 812def _argument_prepare_check():813 global time_unit, fd_task, fd_sum814 if args.filter_tasks:815 args.filter_tasks = args.filter_tasks.split(",")816 if args.limit_to_tasks:817 args.limit_to_tasks = args.limit_to_tasks.split(",")818 if args.time_limit:819 args.time_limit = args.time_limit.split(":")820 for rename_tuple in args.rename_comms_by_tids.split(","):821 tid_name = rename_tuple.split(":")822 if len(tid_name) != 2:823 continue824 args.tid_renames[int(tid_name[0])] = tid_name[1]825 args.highlight_tasks_map = dict()826 for highlight_tasks_tuple in args.highlight_tasks.split(","):827 tasks_color_map = highlight_tasks_tuple.split(":")828 # default highlight color to red if no color set by user829 if len(tasks_color_map) == 1:830 tasks_color_map.append("red")831 if args.highlight_tasks and tasks_color_map[1].lower() not in _COLORS:832 sys.exit(833 "Error: Color not defined, please choose from grey,red,green,yellow,blue,"834 "violet"835 )836 if len(tasks_color_map) != 2:837 continue838 args.highlight_tasks_map[tasks_color_map[0]] = tasks_color_map[1]839 time_unit = "us"840 if args.ns:841 time_unit = "ns"842 elif args.ms:843 time_unit = "ms"844 845 846 fd_task = sys.stdout847 if args.csv:848 args.stdio_color = "never"849 fd_task = open(args.csv, "w")850 print("generating csv at",args.csv,)851 852 fd_sum = sys.stdout853 if args.csv_summary:854 args.stdio_color = "never"855 fd_sum = open(args.csv_summary, "w")856 print("generating csv summary at",args.csv_summary)857 if not args.csv:858 args.summary_only = True859 860 861def _is_within_timelimit(time):862 """863 Check if a time limit was given by parameter, if so ignore the rest. If not,864 process the recorded trace in its entirety.865 """866 if not args.time_limit:867 return True868 lower_time_limit = args.time_limit[0]869 upper_time_limit = args.time_limit[1]870 # check for upper limit871 if upper_time_limit == "":872 if time >= decimal.Decimal(lower_time_limit):873 return True874 # check for lower limit875 if lower_time_limit == "":876 if time <= decimal.Decimal(upper_time_limit):877 return True878 # quit if time exceeds upper limit. Good for big datasets879 else:880 quit()881 if lower_time_limit != "" and upper_time_limit != "":882 if (time >= decimal.Decimal(lower_time_limit) and883 time <= decimal.Decimal(upper_time_limit)):884 return True885 # quit if time exceeds upper limit. Good for big datasets886 elif time > decimal.Decimal(upper_time_limit):887 quit()888 889def _prepare_fmt_precision():890 decimal_precision = 6891 time_precision = 3892 if args.ns:893 decimal_precision = 9894 time_precision = 0895 return decimal_precision, time_precision896 897def _prepare_fmt_sep():898 separator = " "899 fix_csv_align = 1900 if args.csv or args.csv_summary:901 separator = ";"902 fix_csv_align = 0903 return separator, fix_csv_align904 905def trace_unhandled(event_name, context, event_fields_dict, perf_sample_dict):906 pass907 908 909def trace_begin():910 _parse_args()911 _check_color()912 _init_db()913 if not args.summary_only:914 _print_header()915 916def trace_end():917 if args.summary or args.summary_extended or args.summary_only:918 Summary().print()919 920def sched__sched_switch(event_name, context, common_cpu, common_secs, common_nsecs,921 common_pid, common_comm, common_callchain, prev_comm,922 prev_pid, prev_prio, prev_state, next_comm, next_pid,923 next_prio, perf_sample_dict):924 # ignore common_secs & common_nsecs cause we need925 # high res timestamp anyway, using the raw value is926 # faster927 time = _time_to_internal(perf_sample_dict["sample"]["time"])928 if not _is_within_timelimit(time):929 # user specific --time-limit a:b set930 return931 932 next_comm = _filter_non_printable(next_comm)933 _handle_task_finish(prev_pid, common_cpu, time, perf_sample_dict)934 _handle_task_start(next_pid, common_cpu, next_comm, time)935