838 lines · 29.1 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 miliseconds"    )    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",    )    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",)        print(fmt.format(*_header))     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.        """        decimal_precision, time_precision = _prepare_fmt_precision()        fmt = " {{:>{}}}".format(db["task_info"]["pid"])        fmt += " {{:>{}}}".format(db["task_info"]["tid"])        fmt += " {{:>{}}}".format(db["task_info"]["comm"])        fmt += " {{:>{}}}".format(db["runtime_info"]["runs"])        fmt += " {{:>{}}}".format(db["runtime_info"]["acc"])        fmt += " {{:>{}}}".format(db["runtime_info"]["mean"])        fmt += " {{:>{}}}".format(db["runtime_info"]["median"])        fmt += " {{:>{}}}".format(db["runtime_info"]["min"] - decimal_precision)        fmt += " {{:>{}}}".format(db["runtime_info"]["max"] - decimal_precision)        fmt += " {{}}{{:>{}}}{{}}".format(db["runtime_info"]["max_at"] - time_precision)         column_titles = ("PID", "TID", "Comm")        column_titles += ("Runs", "Accumulated", "Mean", "Median", "Min", "Max")        column_titles += (_COLORS["grey"], "At", _COLORS["reset"])         if args.summary_extended:            fmt += " {{:>{}}}".format(db["inter_times"]["out_in"] - decimal_precision)            fmt += " {{}}{{:>{}}}{{}}".format(                db["inter_times"]["inter_at"] - time_precision            )            fmt += " {{:>{}}}".format(db["inter_times"]["out_out"] - decimal_precision)            fmt += " {{:>{}}}".format(db["inter_times"]["in_in"] - decimal_precision)            fmt += " {{:>{}}}".format(db["inter_times"]["in_out"] - decimal_precision)             column_titles += ("Out-In", _COLORS["grey"], "Max At", _COLORS["reset"],                        "Out-Out", "In-In", "In-Out")        print(fmt.format(*column_titles))     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):        decimal_precision, time_precision = _prepare_fmt_precision()        fmt = " {{:>{}d}}".format(db["task_info"]["pid"])        fmt += " {{:>{}d}}".format(db["task_info"]["tid"])        fmt += " {{:>{}}}".format(db["task_info"]["comm"])        fmt += " {{:>{}d}}".format(db["runtime_info"]["runs"])        fmt += " {{:>{}.{}f}}".format(db["runtime_info"]["acc"], time_precision)        fmt += " {{}}{{:>{}.{}f}}".format(db["runtime_info"]["mean"], time_precision)        fmt += " {{:>{}.{}f}}".format(db["runtime_info"]["median"], time_precision)        fmt += " {{:>{}.{}f}}".format(            db["runtime_info"]["min"] - decimal_precision, time_precision            )        fmt += " {{:>{}.{}f}}".format(            db["runtime_info"]["max"] - decimal_precision, time_precision            )        fmt += " {{}}{{:>{}.{}f}}{{}}{{}}".format(            db["runtime_info"]["max_at"] - time_precision, decimal_precision        )        if args.summary_extended:            fmt += " {{:>{}.{}f}}".format(                db["inter_times"]["out_in"] - decimal_precision, time_precision            )            fmt += " {{}}{{:>{}.{}f}}{{}}".format(                db["inter_times"]["inter_at"] - time_precision, decimal_precision            )            fmt += " {{:>{}.{}f}}".format(                db["inter_times"]["out_out"] - decimal_precision, time_precision            )            fmt += " {{:>{}.{}f}}".format(                db["inter_times"]["in_in"] - decimal_precision, time_precision            )            fmt += " {{:>{}.{}f}}".format(                db["inter_times"]["in_out"] - decimal_precision, 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):        print("\nSummary")        self._task_stats()        self._print_header()        self._column_titles()        fmt = self._format_stats()        for i in range(len(self._body)):            print(fmt.format(*tuple(self._body[i])))   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"):

Lines 1–500 of 838.