| # task-analyzer.py - comprehensive perf tasks analysis | |
| # SPDX-License-Identifier: GPL-2.0 | |
| # Copyright (c) 2022, Hagen Paul Pfeifer <hagen@jauu.net> | |
| # Licensed under the terms of the GNU GPL License version 2 | |
| # | |
| # Usage: | |
| # | |
| # perf record -e sched:sched_switch -a -- sleep 10 | |
| # perf script report task-analyzer | |
| # | |
| from __future__ import print_function | |
| import sys | |
| import os | |
| import string | |
| import argparse | |
| import decimal | |
| sys.path.append( | |
| os.environ["PERF_EXEC_PATH"] + "/scripts/python/Perf-Trace-Util/lib/Perf/Trace" | |
| ) | |
| from perf_trace_context import * | |
| from Core import * | |
| # Definition of possible ASCII color codes | |
| _COLORS = { | |
| "grey": "\033[90m", | |
| "red": "\033[91m", | |
| "green": "\033[92m", | |
| "yellow": "\033[93m", | |
| "blue": "\033[94m", | |
| "violet": "\033[95m", | |
| "reset": "\033[0m", | |
| } | |
| # Columns will have a static size to align everything properly | |
| # Support of 116 days of active update with nano precision | |
| LEN_SWITCHED_IN = len("9999999.999999999") # 17 | |
| LEN_SWITCHED_OUT = len("9999999.999999999") # 17 | |
| LEN_CPU = len("000") | |
| LEN_PID = len("maxvalue") # 8 | |
| LEN_TID = len("maxvalue") # 8 | |
| LEN_COMM = len("max-comms-length") # 16 | |
| LEN_RUNTIME = len("999999.999") # 10 | |
| # Support of 3.45 hours of timespans | |
| LEN_OUT_IN = len("99999999999.999") # 15 | |
| LEN_OUT_OUT = len("99999999999.999") # 15 | |
| LEN_IN_IN = len("99999999999.999") # 15 | |
| LEN_IN_OUT = len("99999999999.999") # 15 | |
| # py2/py3 compatibility layer, see PEP469 | |
| try: | |
| dict.iteritems | |
| except AttributeError: | |
| # py3 | |
| def itervalues(d): | |
| return iter(d.values()) | |
| def iteritems(d): | |
| return iter(d.items()) | |
| else: | |
| # py2 | |
| def itervalues(d): | |
| return d.itervalues() | |
| def iteritems(d): | |
| return d.iteritems() | |
| def _check_color(): | |
| global _COLORS | |
| """user enforced no-color or if stdout is no tty we disable colors""" | |
| if sys.stdout.isatty() and args.stdio_color != "never": | |
| return | |
| _COLORS = { | |
| "grey": "", | |
| "red": "", | |
| "green": "", | |
| "yellow": "", | |
| "blue": "", | |
| "violet": "", | |
| "reset": "", | |
| } | |
| def _parse_args(): | |
| global args | |
| parser = argparse.ArgumentParser(description="Analyze tasks behavior") | |
| parser.add_argument( | |
| "--time-limit", | |
| default=[], | |
| help= | |
| "print tasks only in time[s] window e.g" | |
| " --time-limit 123.111:789.222(print all between 123.111 and 789.222)" | |
| " --time-limit 123: (print all from 123)" | |
| " --time-limit :456 (print all until incl. 456)", | |
| ) | |
| parser.add_argument( | |
| "--summary", action="store_true", help="print addtional runtime information" | |
| ) | |
| parser.add_argument( | |
| "--summary-only", action="store_true", help="print only summary without traces" | |
| ) | |
| parser.add_argument( | |
| "--summary-extended", | |
| action="store_true", | |
| help="print the summary with additional information of max inter task times" | |
| " relative to the prev task", | |
| ) | |
| parser.add_argument( | |
| "--ns", action="store_true", help="show timestamps in nanoseconds" | |
| ) | |
| parser.add_argument( | |
| "--ms", action="store_true", help="show timestamps in milliseconds" | |
| ) | |
| parser.add_argument( | |
| "--extended-times", | |
| action="store_true", | |
| help="Show the elapsed times between schedule in/schedule out" | |
| " of this task and the schedule in/schedule out of previous occurrence" | |
| " of the same task", | |
| ) | |
| parser.add_argument( | |
| "--filter-tasks", | |
| default=[], | |
| help="filter out unneeded tasks by tid, pid or processname." | |
| " E.g --filter-task 1337,/sbin/init ", | |
| ) | |
| parser.add_argument( | |
| "--limit-to-tasks", | |
| default=[], | |
| help="limit output to selected task by tid, pid, processname." | |
| " E.g --limit-to-tasks 1337,/sbin/init", | |
| ) | |
| parser.add_argument( | |
| "--highlight-tasks", | |
| default="", | |
| help="colorize special tasks by their pid/tid/comm." | |
| " E.g. --highlight-tasks 1:red,mutt:yellow" | |
| " Colors available: red,grey,yellow,blue,violet,green", | |
| ) | |
| parser.add_argument( | |
| "--rename-comms-by-tids", | |
| default="", | |
| help="rename task names by using tid (<tid>:<newname>,<tid>:<newname>)" | |
| " This option is handy for inexpressive processnames like python interpreted" | |
| " process. E.g --rename 1337:my-python-app", | |
| ) | |
| parser.add_argument( | |
| "--stdio-color", | |
| default="auto", | |
| choices=["always", "never", "auto"], | |
| help="always, never or auto, allowing configuring color output" | |
| " via the command line", | |
| ) | |
| parser.add_argument( | |
| "--csv", | |
| default="", | |
| help="Write trace to file selected by user. Options, like --ns or --extended" | |
| "-times are used.", | |
| ) | |
| parser.add_argument( | |
| "--csv-summary", | |
| default="", | |
| help="Write summary to file selected by user. Options, like --ns or" | |
| " --summary-extended are used.", | |
| ) | |
| args = parser.parse_args() | |
| args.tid_renames = dict() | |
| _argument_filter_sanity_check() | |
| _argument_prepare_check() | |
| def time_uniter(unit): | |
| picker = { | |
| "s": 1, | |
| "ms": 1e3, | |
| "us": 1e6, | |
| "ns": 1e9, | |
| } | |
| return picker[unit] | |
| def _init_db(): | |
| global db | |
| db = dict() | |
| db["running"] = dict() | |
| db["cpu"] = dict() | |
| db["tid"] = dict() | |
| db["global"] = [] | |
| if args.summary or args.summary_extended or args.summary_only: | |
| db["task_info"] = dict() | |
| db["runtime_info"] = dict() | |
| # min values for summary depending on the header | |
| db["task_info"]["pid"] = len("PID") | |
| db["task_info"]["tid"] = len("TID") | |
| db["task_info"]["comm"] = len("Comm") | |
| db["runtime_info"]["runs"] = len("Runs") | |
| db["runtime_info"]["acc"] = len("Accumulated") | |
| db["runtime_info"]["max"] = len("Max") | |
| db["runtime_info"]["max_at"] = len("Max At") | |
| db["runtime_info"]["min"] = len("Min") | |
| db["runtime_info"]["mean"] = len("Mean") | |
| db["runtime_info"]["median"] = len("Median") | |
| if args.summary_extended: | |
| db["inter_times"] = dict() | |
| db["inter_times"]["out_in"] = len("Out-In") | |
| db["inter_times"]["inter_at"] = len("At") | |
| db["inter_times"]["out_out"] = len("Out-Out") | |
| db["inter_times"]["in_in"] = len("In-In") | |
| db["inter_times"]["in_out"] = len("In-Out") | |
| def _median(numbers): | |
| """phython3 hat statistics module - we have nothing""" | |
| n = len(numbers) | |
| index = n // 2 | |
| if n % 2: | |
| return sorted(numbers)[index] | |
| return sum(sorted(numbers)[index - 1 : index + 1]) / 2 | |
| def _mean(numbers): | |
| return sum(numbers) / len(numbers) | |
| class Timespans(object): | |
| """ | |
| The elapsed time between two occurrences of the same task is being tracked with the | |
| help of this class. There are 4 of those Timespans Out-Out, In-Out, Out-In and | |
| In-In. | |
| The first half of the name signals the first time point of the | |
| first task. The second half of the name represents the second | |
| timepoint of the second task. | |
| """ | |
| def __init__(self): | |
| self._last_start = None | |
| self._last_finish = None | |
| self.out_out = -1 | |
| self.in_out = -1 | |
| self.out_in = -1 | |
| self.in_in = -1 | |
| if args.summary_extended: | |
| self._time_in = -1 | |
| self.max_out_in = -1 | |
| self.max_at = -1 | |
| self.max_in_out = -1 | |
| self.max_in_in = -1 | |
| self.max_out_out = -1 | |
| def feed(self, task): | |
| """ | |
| Called for every recorded trace event to find process pair and calculate the | |
| task timespans. Chronological ordering, feed does not do reordering | |
| """ | |
| if not self._last_finish: | |
| self._last_start = task.time_in(time_unit) | |
| self._last_finish = task.time_out(time_unit) | |
| return | |
| self._time_in = task.time_in() | |
| time_in = task.time_in(time_unit) | |
| time_out = task.time_out(time_unit) | |
| self.in_in = time_in - self._last_start | |
| self.out_in = time_in - self._last_finish | |
| self.in_out = time_out - self._last_start | |
| self.out_out = time_out - self._last_finish | |
| if args.summary_extended: | |
| self._update_max_entries() | |
| self._last_finish = task.time_out(time_unit) | |
| self._last_start = task.time_in(time_unit) | |
| def _update_max_entries(self): | |
| if self.in_in > self.max_in_in: | |
| self.max_in_in = self.in_in | |
| if self.out_out > self.max_out_out: | |
| self.max_out_out = self.out_out | |
| if self.in_out > self.max_in_out: | |
| self.max_in_out = self.in_out | |
| if self.out_in > self.max_out_in: | |
| self.max_out_in = self.out_in | |
| self.max_at = self._time_in | |
| class Summary(object): | |
| """ | |
| Primary instance for calculating the summary output. Processes the whole trace to | |
| find and memorize relevant data such as mean, max et cetera. This instance handles | |
| dynamic alignment aspects for summary output. | |
| """ | |
| def __init__(self): | |
| self._body = [] | |
| class AlignmentHelper: | |
| """ | |
| Used to calculated the alignment for the output of the summary. | |
| """ | |
| def __init__(self, pid, tid, comm, runs, acc, mean, | |
| median, min, max, max_at): | |
| self.pid = pid | |
| self.tid = tid | |
| self.comm = comm | |
| self.runs = runs | |
| self.acc = acc | |
| self.mean = mean | |
| self.median = median | |
| self.min = min | |
| self.max = max | |
| self.max_at = max_at | |
| if args.summary_extended: | |
| self.out_in = None | |
| self.inter_at = None | |
| self.out_out = None | |
| self.in_in = None | |
| self.in_out = None | |
| def _print_header(self): | |
| ''' | |
| Output is trimmed in _format_stats thus additional adjustment in the header | |
| is needed, depending on the choice of timeunit. The adjustment corresponds | |
| to the amount of column titles being adjusted in _column_titles. | |
| ''' | |
| decimal_precision = 6 if not args.ns else 9 | |
| fmt = " {{:^{}}}".format(sum(db["task_info"].values())) | |
| fmt += " {{:^{}}}".format( | |
| sum(db["runtime_info"].values()) - 2 * decimal_precision | |
| ) | |
| _header = ("Task Information", "Runtime Information") | |
| if args.summary_extended: | |
| fmt += " {{:^{}}}".format( | |
| sum(db["inter_times"].values()) - 4 * decimal_precision | |
| ) | |
| _header += ("Max Inter Task Times",) | |
| fd_sum.write(fmt.format(*_header) + "\n") | |
| def _column_titles(self): | |
| """ | |
| Cells are being processed and displayed in different way so an alignment adjust | |
| is implemented depeding on the choice of the timeunit. The positions of the max | |
| values are being displayed in grey. Thus in their format two additional {}, | |
| are placed for color set and reset. | |
| """ | |
| separator, fix_csv_align = _prepare_fmt_sep() | |
| decimal_precision, time_precision = _prepare_fmt_precision() | |
| fmt = "{{:>{}}}".format(db["task_info"]["pid"] * fix_csv_align) | |
| fmt += "{}{{:>{}}}".format(separator, db["task_info"]["tid"] * fix_csv_align) | |
| fmt += "{}{{:>{}}}".format(separator, db["task_info"]["comm"] * fix_csv_align) | |
| fmt += "{}{{:>{}}}".format(separator, db["runtime_info"]["runs"] * fix_csv_align) | |
| fmt += "{}{{:>{}}}".format(separator, db["runtime_info"]["acc"] * fix_csv_align) | |
| fmt += "{}{{:>{}}}".format(separator, db["runtime_info"]["mean"] * fix_csv_align) | |
| fmt += "{}{{:>{}}}".format( | |
| separator, db["runtime_info"]["median"] * fix_csv_align | |
| ) | |
| fmt += "{}{{:>{}}}".format( | |
| separator, (db["runtime_info"]["min"] - decimal_precision) * fix_csv_align | |
| ) | |
| fmt += "{}{{:>{}}}".format( | |
| separator, (db["runtime_info"]["max"] - decimal_precision) * fix_csv_align | |
| ) | |
| fmt += "{}{{}}{{:>{}}}{{}}".format( | |
| separator, (db["runtime_info"]["max_at"] - time_precision) * fix_csv_align | |
| ) | |
| column_titles = ("PID", "TID", "Comm") | |
| column_titles += ("Runs", "Accumulated", "Mean", "Median", "Min", "Max") | |
| column_titles += (_COLORS["grey"], "Max At", _COLORS["reset"]) | |
| if args.summary_extended: | |
| fmt += "{}{{:>{}}}".format( | |
| separator, | |
| (db["inter_times"]["out_in"] - decimal_precision) * fix_csv_align | |
| ) | |
| fmt += "{}{{}}{{:>{}}}{{}}".format( | |
| separator, | |
| (db["inter_times"]["inter_at"] - time_precision) * fix_csv_align | |
| ) | |
| fmt += "{}{{:>{}}}".format( | |
| separator, | |
| (db["inter_times"]["out_out"] - decimal_precision) * fix_csv_align | |
| ) | |
| fmt += "{}{{:>{}}}".format( | |
| separator, | |
| (db["inter_times"]["in_in"] - decimal_precision) * fix_csv_align | |
| ) | |
| fmt += "{}{{:>{}}}".format( | |
| separator, | |
| (db["inter_times"]["in_out"] - decimal_precision) * fix_csv_align | |
| ) | |
| column_titles += ("Out-In", _COLORS["grey"], "Max At", _COLORS["reset"], | |
| "Out-Out", "In-In", "In-Out") | |
| fd_sum.write(fmt.format(*column_titles) + "\n") | |
| def _task_stats(self): | |
| """calculates the stats of every task and constructs the printable summary""" | |
| for tid in sorted(db["tid"]): | |
| color_one_sample = _COLORS["grey"] | |
| color_reset = _COLORS["reset"] | |
| no_executed = 0 | |
| runtimes = [] | |
| time_in = [] | |
| timespans = Timespans() | |
| for task in db["tid"][tid]: | |
| pid = task.pid | |
| comm = task.comm | |
| no_executed += 1 | |
| runtimes.append(task.runtime(time_unit)) | |
| time_in.append(task.time_in()) | |
| timespans.feed(task) | |
| if len(runtimes) > 1: | |
| color_one_sample = "" | |
| color_reset = "" | |
| time_max = max(runtimes) | |
| time_min = min(runtimes) | |
| max_at = time_in[runtimes.index(max(runtimes))] | |
| # The size of the decimal after sum,mean and median varies, thus we cut | |
| # the decimal number, by rounding it. It has no impact on the output, | |
| # because we have a precision of the decimal points at the output. | |
| time_sum = round(sum(runtimes), 3) | |
| time_mean = round(_mean(runtimes), 3) | |
| time_median = round(_median(runtimes), 3) | |
| align_helper = self.AlignmentHelper(pid, tid, comm, no_executed, time_sum, | |
| time_mean, time_median, time_min, time_max, max_at) | |
| self._body.append([pid, tid, comm, no_executed, time_sum, color_one_sample, | |
| time_mean, time_median, time_min, time_max, | |
| _COLORS["grey"], max_at, _COLORS["reset"], color_reset]) | |
| if args.summary_extended: | |
| self._body[-1].extend([timespans.max_out_in, | |
| _COLORS["grey"], timespans.max_at, | |
| _COLORS["reset"], timespans.max_out_out, | |
| timespans.max_in_in, | |
| timespans.max_in_out]) | |
| align_helper.out_in = timespans.max_out_in | |
| align_helper.inter_at = timespans.max_at | |
| align_helper.out_out = timespans.max_out_out | |
| align_helper.in_in = timespans.max_in_in | |
| align_helper.in_out = timespans.max_in_out | |
| self._calc_alignments_summary(align_helper) | |
| def _format_stats(self): | |
| separator, fix_csv_align = _prepare_fmt_sep() | |
| decimal_precision, time_precision = _prepare_fmt_precision() | |
| len_pid = db["task_info"]["pid"] * fix_csv_align | |
| len_tid = db["task_info"]["tid"] * fix_csv_align | |
| len_comm = db["task_info"]["comm"] * fix_csv_align | |
| len_runs = db["runtime_info"]["runs"] * fix_csv_align | |
| len_acc = db["runtime_info"]["acc"] * fix_csv_align | |
| len_mean = db["runtime_info"]["mean"] * fix_csv_align | |
| len_median = db["runtime_info"]["median"] * fix_csv_align | |
| len_min = (db["runtime_info"]["min"] - decimal_precision) * fix_csv_align | |
| len_max = (db["runtime_info"]["max"] - decimal_precision) * fix_csv_align | |
| len_max_at = (db["runtime_info"]["max_at"] - time_precision) * fix_csv_align | |
| if args.summary_extended: | |
| len_out_in = ( | |
| db["inter_times"]["out_in"] - decimal_precision | |
| ) * fix_csv_align | |
| len_inter_at = ( | |
| db["inter_times"]["inter_at"] - time_precision | |
| ) * fix_csv_align | |
| len_out_out = ( | |
| db["inter_times"]["out_out"] - decimal_precision | |
| ) * fix_csv_align | |
| len_in_in = (db["inter_times"]["in_in"] - decimal_precision) * fix_csv_align | |
| len_in_out = ( | |
| db["inter_times"]["in_out"] - decimal_precision | |
| ) * fix_csv_align | |
| fmt = "{{:{}d}}".format(len_pid) | |
| fmt += "{}{{:{}d}}".format(separator, len_tid) | |
| fmt += "{}{{:>{}}}".format(separator, len_comm) | |
| fmt += "{}{{:{}d}}".format(separator, len_runs) | |
| fmt += "{}{{:{}.{}f}}".format(separator, len_acc, time_precision) | |
| fmt += "{}{{}}{{:{}.{}f}}".format(separator, len_mean, time_precision) | |
| fmt += "{}{{:{}.{}f}}".format(separator, len_median, time_precision) | |
| fmt += "{}{{:{}.{}f}}".format(separator, len_min, time_precision) | |
| fmt += "{}{{:{}.{}f}}".format(separator, len_max, time_precision) | |
| fmt += "{}{{}}{{:{}.{}f}}{{}}{{}}".format( | |
| separator, len_max_at, decimal_precision | |
| ) | |
| if args.summary_extended: | |
| fmt += "{}{{:{}.{}f}}".format(separator, len_out_in, time_precision) | |
| fmt += "{}{{}}{{:{}.{}f}}{{}}".format( | |
| separator, len_inter_at, decimal_precision | |
| ) | |
| fmt += "{}{{:{}.{}f}}".format(separator, len_out_out, time_precision) | |
| fmt += "{}{{:{}.{}f}}".format(separator, len_in_in, time_precision) | |
| fmt += "{}{{:{}.{}f}}".format(separator, len_in_out, time_precision) | |
| return fmt | |
| def _calc_alignments_summary(self, align_helper): | |
| # Length is being cut in 3 groups so that further addition is easier to handle. | |
| # The length of every argument from the alignment helper is being checked if it | |
| # is longer than the longest until now. In that case the length is being saved. | |
| for key in db["task_info"]: | |
| if len(str(getattr(align_helper, key))) > db["task_info"][key]: | |
| db["task_info"][key] = len(str(getattr(align_helper, key))) | |
| for key in db["runtime_info"]: | |
| if len(str(getattr(align_helper, key))) > db["runtime_info"][key]: | |
| db["runtime_info"][key] = len(str(getattr(align_helper, key))) | |
| if args.summary_extended: | |
| for key in db["inter_times"]: | |
| if len(str(getattr(align_helper, key))) > db["inter_times"][key]: | |
| db["inter_times"][key] = len(str(getattr(align_helper, key))) | |
| def print(self): | |
| self._task_stats() | |
| fmt = self._format_stats() | |
| if not args.csv_summary: | |
| print("\nSummary") | |
| self._print_header() | |
| self._column_titles() | |
| for i in range(len(self._body)): | |
| fd_sum.write(fmt.format(*tuple(self._body[i])) + "\n") | |
| class Task(object): | |
| """ The class is used to handle the information of a given task.""" | |
| def __init__(self, id, tid, cpu, comm): | |
| self.id = id | |
| self.tid = tid | |
| self.cpu = cpu | |
| self.comm = comm | |
| self.pid = None | |
| self._time_in = None | |
| self._time_out = None | |
| def schedule_in_at(self, time): | |
| """set the time where the task was scheduled in""" | |
| self._time_in = time | |
| def schedule_out_at(self, time): | |
| """set the time where the task was scheduled out""" | |
| self._time_out = time | |
| def time_out(self, unit="s"): | |
| """return time where a given task was scheduled out""" | |
| factor = time_uniter(unit) | |
| return self._time_out * decimal.Decimal(factor) | |
| def time_in(self, unit="s"): | |
| """return time where a given task was scheduled in""" | |
| factor = time_uniter(unit) | |
| return self._time_in * decimal.Decimal(factor) | |
| def runtime(self, unit="us"): | |
| factor = time_uniter(unit) | |
| return (self._time_out - self._time_in) * decimal.Decimal(factor) | |
| def update_pid(self, pid): | |
| self.pid = pid | |
| def _task_id(pid, cpu): | |
| """returns a "unique-enough" identifier, please do not change""" | |
| return "{}-{}".format(pid, cpu) | |
| def _filter_non_printable(unfiltered): | |
| """comm names may contain loony chars like '\x00000'""" | |
| filtered = "" | |
| for char in unfiltered: | |
| if char not in string.printable: | |
| continue | |
| filtered += char | |
| return filtered | |
| def _fmt_header(): | |
| separator, fix_csv_align = _prepare_fmt_sep() | |
| fmt = "{{:>{}}}".format(LEN_SWITCHED_IN*fix_csv_align) | |
| fmt += "{}{{:>{}}}".format(separator, LEN_SWITCHED_OUT*fix_csv_align) | |
| fmt += "{}{{:>{}}}".format(separator, LEN_CPU*fix_csv_align) | |
| fmt += "{}{{:>{}}}".format(separator, LEN_PID*fix_csv_align) | |
| fmt += "{}{{:>{}}}".format(separator, LEN_TID*fix_csv_align) | |
| fmt += "{}{{:>{}}}".format(separator, LEN_COMM*fix_csv_align) | |
| fmt += "{}{{:>{}}}".format(separator, LEN_RUNTIME*fix_csv_align) | |
| fmt += "{}{{:>{}}}".format(separator, LEN_OUT_IN*fix_csv_align) | |
| if args.extended_times: | |
| fmt += "{}{{:>{}}}".format(separator, LEN_OUT_OUT*fix_csv_align) | |
| fmt += "{}{{:>{}}}".format(separator, LEN_IN_IN*fix_csv_align) | |
| fmt += "{}{{:>{}}}".format(separator, LEN_IN_OUT*fix_csv_align) | |
| return fmt | |
| def _fmt_body(): | |
| separator, fix_csv_align = _prepare_fmt_sep() | |
| decimal_precision, time_precision = _prepare_fmt_precision() | |
| fmt = "{{}}{{:{}.{}f}}".format(LEN_SWITCHED_IN*fix_csv_align, decimal_precision) | |
| fmt += "{}{{:{}.{}f}}".format( | |
| separator, LEN_SWITCHED_OUT*fix_csv_align, decimal_precision | |
| ) | |
| fmt += "{}{{:{}d}}".format(separator, LEN_CPU*fix_csv_align) | |
| fmt += "{}{{:{}d}}".format(separator, LEN_PID*fix_csv_align) | |
| fmt += "{}{{}}{{:{}d}}{{}}".format(separator, LEN_TID*fix_csv_align) | |
| fmt += "{}{{}}{{:>{}}}".format(separator, LEN_COMM*fix_csv_align) | |
| fmt += "{}{{:{}.{}f}}".format(separator, LEN_RUNTIME*fix_csv_align, time_precision) | |
| if args.extended_times: | |
| fmt += "{}{{:{}.{}f}}".format(separator, LEN_OUT_IN*fix_csv_align, time_precision) | |
| fmt += "{}{{:{}.{}f}}".format(separator, LEN_OUT_OUT*fix_csv_align, time_precision) | |
| fmt += "{}{{:{}.{}f}}".format(separator, LEN_IN_IN*fix_csv_align, time_precision) | |
| fmt += "{}{{:{}.{}f}}{{}}".format( | |
| separator, LEN_IN_OUT*fix_csv_align, time_precision | |
| ) | |
| else: | |
| fmt += "{}{{:{}.{}f}}{{}}".format( | |
| separator, LEN_OUT_IN*fix_csv_align, time_precision | |
| ) | |
| return fmt | |
| def _print_header(): | |
| fmt = _fmt_header() | |
| header = ("Switched-In", "Switched-Out", "CPU", "PID", "TID", "Comm", "Runtime", | |
| "Time Out-In") | |
| if args.extended_times: | |
| header += ("Time Out-Out", "Time In-In", "Time In-Out") | |
| fd_task.write(fmt.format(*header) + "\n") | |
| def _print_task_finish(task): | |
| """calculating every entry of a row and printing it immediately""" | |
| c_row_set = "" | |
| c_row_reset = "" | |
| out_in = -1 | |
| out_out = -1 | |
| in_in = -1 | |
| in_out = -1 | |
| fmt = _fmt_body() | |
| # depending on user provided highlight option we change the color | |
| # for particular tasks | |
| if str(task.tid) in args.highlight_tasks_map: | |
| c_row_set = _COLORS[args.highlight_tasks_map[str(task.tid)]] | |
| c_row_reset = _COLORS["reset"] | |
| if task.comm in args.highlight_tasks_map: | |
| c_row_set = _COLORS[args.highlight_tasks_map[task.comm]] | |
| c_row_reset = _COLORS["reset"] | |
| # grey-out entries if PID == TID, they | |
| # are identical, no threaded model so the | |
| # thread id (tid) do not matter | |
| c_tid_set = "" | |
| c_tid_reset = "" | |
| if task.pid == task.tid: | |
| c_tid_set = _COLORS["grey"] | |
| c_tid_reset = _COLORS["reset"] | |
| if task.tid in db["tid"]: | |
| # get last task of tid | |
| last_tid_task = db["tid"][task.tid][-1] | |
| # feed the timespan calculate, last in tid db | |
| # and second the current one | |
| timespan_gap_tid = Timespans() | |
| timespan_gap_tid.feed(last_tid_task) | |
| timespan_gap_tid.feed(task) | |
| out_in = timespan_gap_tid.out_in | |
| out_out = timespan_gap_tid.out_out | |
| in_in = timespan_gap_tid.in_in | |
| in_out = timespan_gap_tid.in_out | |
| if args.extended_times: | |
| line_out = fmt.format(c_row_set, task.time_in(), task.time_out(), task.cpu, | |
| task.pid, c_tid_set, task.tid, c_tid_reset, c_row_set, task.comm, | |
| task.runtime(time_unit), out_in, out_out, in_in, in_out, | |
| c_row_reset) + "\n" | |
| else: | |
| line_out = fmt.format(c_row_set, task.time_in(), task.time_out(), task.cpu, | |
| task.pid, c_tid_set, task.tid, c_tid_reset, c_row_set, task.comm, | |
| task.runtime(time_unit), out_in, c_row_reset) + "\n" | |
| try: | |
| fd_task.write(line_out) | |
| except(IOError): | |
| # don't mangle the output if user SIGINT this script | |
| sys.exit() | |
| def _record_cleanup(_list): | |
| """ | |
| no need to store more then one element if --summarize | |
| is not enabled | |
| """ | |
| if not args.summary and len(_list) > 1: | |
| _list = _list[len(_list) - 1 :] | |
| def _record_by_tid(task): | |
| tid = task.tid | |
| if tid not in db["tid"]: | |
| db["tid"][tid] = [] | |
| db["tid"][tid].append(task) | |
| _record_cleanup(db["tid"][tid]) | |
| def _record_by_cpu(task): | |
| cpu = task.cpu | |
| if cpu not in db["cpu"]: | |
| db["cpu"][cpu] = [] | |
| db["cpu"][cpu].append(task) | |
| _record_cleanup(db["cpu"][cpu]) | |
| def _record_global(task): | |
| """record all executed task, ordered by finish chronological""" | |
| db["global"].append(task) | |
| _record_cleanup(db["global"]) | |
| def _handle_task_finish(tid, cpu, time, perf_sample_dict): | |
| if tid == 0: | |
| return | |
| _id = _task_id(tid, cpu) | |
| if _id not in db["running"]: | |
| # may happen, if we missed the switch to | |
| # event. Seen in combination with --exclude-perf | |
| # where the start is filtered out, but not the | |
| # switched in. Probably a bug in exclude-perf | |
| # option. | |
| return | |
| task = db["running"][_id] | |
| task.schedule_out_at(time) | |
| # record tid, during schedule in the tid | |
| # is not available, update now | |
| pid = int(perf_sample_dict["sample"]["pid"]) | |
| task.update_pid(pid) | |
| del db["running"][_id] | |
| # print only tasks which are not being filtered and no print of trace | |
| # for summary only, but record every task. | |
| if not _limit_filtered(tid, pid, task.comm) and not args.summary_only: | |
| _print_task_finish(task) | |
| _record_by_tid(task) | |
| _record_by_cpu(task) | |
| _record_global(task) | |
| def _handle_task_start(tid, cpu, comm, time): | |
| if tid == 0: | |
| return | |
| if tid in args.tid_renames: | |
| comm = args.tid_renames[tid] | |
| _id = _task_id(tid, cpu) | |
| if _id in db["running"]: | |
| # handle corner cases where already running tasks | |
| # are switched-to again - saw this via --exclude-perf | |
| # recorded traces. We simple ignore this "second start" | |
| # event. | |
| return | |
| assert _id not in db["running"] | |
| task = Task(_id, tid, cpu, comm) | |
| task.schedule_in_at(time) | |
| db["running"][_id] = task | |
| def _time_to_internal(time_ns): | |
| """ | |
| To prevent float rounding errors we use Decimal internally | |
| """ | |
| return decimal.Decimal(time_ns) / decimal.Decimal(1e9) | |
| def _limit_filtered(tid, pid, comm): | |
| if args.filter_tasks: | |
| if str(tid) in args.filter_tasks or comm in args.filter_tasks: | |
| return True | |
| else: | |
| return False | |
| if args.limit_to_tasks: | |
| if str(tid) in args.limit_to_tasks or comm in args.limit_to_tasks: | |
| return False | |
| else: | |
| return True | |
| def _argument_filter_sanity_check(): | |
| if args.limit_to_tasks and args.filter_tasks: | |
| sys.exit("Error: Filter and Limit at the same time active.") | |
| if args.extended_times and args.summary_only: | |
| sys.exit("Error: Summary only and extended times active.") | |
| if args.time_limit and ":" not in args.time_limit: | |
| sys.exit( | |
| "Error: No bound set for time limit. Please set bound by ':' e.g :123." | |
| ) | |
| if args.time_limit and (args.summary or args.summary_only or args.summary_extended): | |
| sys.exit("Error: Cannot set time limit and print summary") | |
| if args.csv_summary: | |
| args.summary = True | |
| if args.csv == args.csv_summary: | |
| sys.exit("Error: Chosen files for csv and csv summary are the same") | |
| if args.csv and (args.summary_extended or args.summary) and not args.csv_summary: | |
| sys.exit("Error: No file chosen to write summary to. Choose with --csv-summary " | |
| "<file>") | |
| if args.csv and args.summary_only: | |
| sys.exit("Error: --csv chosen and --summary-only. Standard task would not be" | |
| "written to csv file.") | |
| def _argument_prepare_check(): | |
| global time_unit, fd_task, fd_sum | |
| if args.filter_tasks: | |
| args.filter_tasks = args.filter_tasks.split(",") | |
| if args.limit_to_tasks: | |
| args.limit_to_tasks = args.limit_to_tasks.split(",") | |
| if args.time_limit: | |
| args.time_limit = args.time_limit.split(":") | |
| for rename_tuple in args.rename_comms_by_tids.split(","): | |
| tid_name = rename_tuple.split(":") | |
| if len(tid_name) != 2: | |
| continue | |
| args.tid_renames[int(tid_name[0])] = tid_name[1] | |
| args.highlight_tasks_map = dict() | |
| for highlight_tasks_tuple in args.highlight_tasks.split(","): | |
| tasks_color_map = highlight_tasks_tuple.split(":") | |
| # default highlight color to red if no color set by user | |
| if len(tasks_color_map) == 1: | |
| tasks_color_map.append("red") | |
| if args.highlight_tasks and tasks_color_map[1].lower() not in _COLORS: | |
| sys.exit( | |
| "Error: Color not defined, please choose from grey,red,green,yellow,blue," | |
| "violet" | |
| ) | |
| if len(tasks_color_map) != 2: | |
| continue | |
| args.highlight_tasks_map[tasks_color_map[0]] = tasks_color_map[1] | |
| time_unit = "us" | |
| if args.ns: | |
| time_unit = "ns" | |
| elif args.ms: | |
| time_unit = "ms" | |
| fd_task = sys.stdout | |
| if args.csv: | |
| args.stdio_color = "never" | |
| fd_task = open(args.csv, "w") | |
| print("generating csv at",args.csv,) | |
| fd_sum = sys.stdout | |
| if args.csv_summary: | |
| args.stdio_color = "never" | |
| fd_sum = open(args.csv_summary, "w") | |
| print("generating csv summary at",args.csv_summary) | |
| if not args.csv: | |
| args.summary_only = True | |
| def _is_within_timelimit(time): | |
| """ | |
| Check if a time limit was given by parameter, if so ignore the rest. If not, | |
| process the recorded trace in its entirety. | |
| """ | |
| if not args.time_limit: | |
| return True | |
| lower_time_limit = args.time_limit[0] | |
| upper_time_limit = args.time_limit[1] | |
| # check for upper limit | |
| if upper_time_limit == "": | |
| if time >= decimal.Decimal(lower_time_limit): | |
| return True | |
| # check for lower limit | |
| if lower_time_limit == "": | |
| if time <= decimal.Decimal(upper_time_limit): | |
| return True | |
| # quit if time exceeds upper limit. Good for big datasets | |
| else: | |
| quit() | |
| if lower_time_limit != "" and upper_time_limit != "": | |
| if (time >= decimal.Decimal(lower_time_limit) and | |
| time <= decimal.Decimal(upper_time_limit)): | |
| return True | |
| # quit if time exceeds upper limit. Good for big datasets | |
| elif time > decimal.Decimal(upper_time_limit): | |
| quit() | |
| def _prepare_fmt_precision(): | |
| decimal_precision = 6 | |
| time_precision = 3 | |
| if args.ns: | |
| decimal_precision = 9 | |
| time_precision = 0 | |
| return decimal_precision, time_precision | |
| def _prepare_fmt_sep(): | |
| separator = " " | |
| fix_csv_align = 1 | |
| if args.csv or args.csv_summary: | |
| separator = ";" | |
| fix_csv_align = 0 | |
| return separator, fix_csv_align | |
| def trace_unhandled(event_name, context, event_fields_dict, perf_sample_dict): | |
| pass | |
| def trace_begin(): | |
| _parse_args() | |
| _check_color() | |
| _init_db() | |
| if not args.summary_only: | |
| _print_header() | |
| def trace_end(): | |
| if args.summary or args.summary_extended or args.summary_only: | |
| Summary().print() | |
| def sched__sched_switch(event_name, context, common_cpu, common_secs, common_nsecs, | |
| common_pid, common_comm, common_callchain, prev_comm, | |
| prev_pid, prev_prio, prev_state, next_comm, next_pid, | |
| next_prio, perf_sample_dict): | |
| # ignore common_secs & common_nsecs cause we need | |
| # high res timestamp anyway, using the raw value is | |
| # faster | |
| time = _time_to_internal(perf_sample_dict["sample"]["time"]) | |
| if not _is_within_timelimit(time): | |
| # user specific --time-limit a:b set | |
| return | |
| next_comm = _filter_non_printable(next_comm) | |
| _handle_task_finish(prev_pid, common_cpu, time, perf_sample_dict) | |
| _handle_task_start(next_pid, common_cpu, next_comm, time) |