934 lines · 33.2 KB · Python
RawDownload
# 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_functionimport sysimport osimport stringimport argparseimport 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 precisionLEN_SWITCHED_IN = len("9999999.999999999")  # 17LEN_SWITCHED_OUT = len("9999999.999999999")  # 17LEN_CPU = len("000")LEN_PID = len("maxvalue")  # 8LEN_TID = len("maxvalue")  # 8LEN_COMM = len("max-comms-length")  # 16LEN_RUNTIME = len("999999.999")  # 10# Support of 3.45 hours of timespansLEN_OUT_IN = len("99999999999.999")  # 15LEN_OUT_OUT = len("99999999999.999")  # 15LEN_IN_IN = len("99999999999.999")  # 15LEN_IN_OUT = len("99999999999.999")  # 15  # py2/py3 compatibility layer, see PEP469try:    dict.iteritemsexcept 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 

Lines 1–500 of 934.