Messages in this thread | | | From | Ian Rogers <> | Date | Thu, 1 Dec 2022 16:05:15 -0800 | Subject | Re: [PATCH 1/2] perf script: introduce task analyzer |
| |
On Thu, Dec 1, 2022 at 11:36 AM Petar Gligoric <petar.gligor@gmail.com> wrote: > > From: Hagen Paul Pfeifer <hagen@jauu.net> > > Introduce a new perf script to analyze task scheduling behavior. > > During the task analysis, some data is always needed - which goes beyond the > simple time of switching on and off a task (process/thread). This concerns for > example the runtime of a process or the frequency with which the process was > called. This script serves to simplify this recurring analyze process. It > immediately provides the user with helpful task characteristic information > about the tasks runtimes. > > Usage: > > Recorded can be in two ways: > $ perf script record tasks-analyzer -- sleep 10 > $ perf record -e sched:sched_switch -a -- sleep 10 > > The script can parse all perf.data files, most important: sched:sched_switch > events are mandatory, other events will be ignored. > > Most simple report use case is to just call the script without arguments: > > $ perf script report tasks-analyzer > Switched-In Switched-Out CPU PID TID Comm Runtime Time Out-In > 15576.658891407 15576.659156086 4 2412 2428 gdbus 265 1949 > 15576.659111320 15576.659455410 0 2412 2412 gnome-shell 344 2267 > 15576.659491326 15576.659506173 2 74 74 kworker/2:1 15 13145 > 15576.659506173 15576.659825748 2 2858 2858 gnome-terminal- 320 63263 > 15576.659871270 15576.659902872 6 20932 20932 kworker/u16:0 32 2314582 > 15576.659909951 15576.659945501 3 27264 27264 sh 36 -1 > 15576.659853285 15576.659971052 7 27265 27265 perf 118 5050741 > [...] > > What is not shown here are the ASCII color sequences. For example, if the task > consists of only one thread, the TID is grayed out. > > Runtime is the time the task was running on the CPU, Time Out-In is the time > between the process being scheduled *out* and scheduled back *in*. So the last > time span between two executions. If -1 is printed, then the task simply ran the > first time in the measurements - a Out-In delta could not be calculated. > > In addition to the chronological representation, there is a summary on task > level. This output can be additionally switched on via the --summary option > and provides information such as max, min & average runtime per process. The > maximum runtime is often important for debugging. The call looks like this: > > $ perf script report tasks-analyzer --summary > Summary > Task Information Runtime Information > PID TID Comm Runs Accumulated Mean Median Min Max Max At > 14 14 ksoftirqd/0 13 334 26 15 9 127 15571.621211956 > 15 15 rcu_preempt 133 1778 13 13 2 33 15572.581176024 > 16 16 migration/0 3 49 16 13 12 24 15571.608915425 > 20 20 migration/1 3 34 11 13 8 13 15571.639101555 > 25 25 migration/2 3 32 11 12 9 12 15575.639239896 > [...] > > Besides these two options, there are a number of other options that change the > output and behavior. This can be queried via --help. Options worth mentioning include: > > - filter-tasks - filter out unneeded tasks, --filter-task 1337,/sbin/init > - highlight-tasks - more pleasant focusing, --highlight-tasks 1:red,mutt:yellow > - extended-times - show combinations of elapsed times between schedule in/schedule out > - summary-extended - summary with additional information, like maximum delta time statistics > - rename-comms-by-tids - handy for inexpressive processnames like python, --rename 1337:my-python-app > - ms - show timestamps in milliseconds, nanoseconds is also possible (--ns) > - time-limit - limit the analyzer to a time range, --time-limit 15576.0:15576.1 > > Script is tested and prime time ready for python2 & python3: > - make PYTHON=python3 prefix=/usr/local install > - make PYTHON=python2 prefix=/usr/local install
Thanks Peter, Python2 isn't a thing any more. It is worth knowing that for python3 you can test old versions easily with docker: docker run -it --rm --name my-running-script -v "$PWD":/usr/src/myapp -w /usr/src/myapp python:3.6 python <script to test> Python 3.6 is 5 years old and what the jevents.py script aims to support. This allows type annotations and f-strings, both of which can make your code more pythonic.
Given the new functionality of this code a test would be useful to avoid regressions. You can invoke perf as part of a shell test: https://git.kernel.org/pub/scm/linux/kernel/git/acme/linux.git/tree/tools/perf/tests/shell?h=perf/core The perf command found is the current running perf command, as its directory is appended to the front of PATH. Could you look to add a test? You could have individual subtests for the different command line flags.
Thanks, Ian
> Signed-off-by: Hagen Paul Pfeifer <hagen@jauu.net> > Signed-off-by: Petar Gligoric <petar.gligoric@rohde-schwarz.com> > Cc: Arnaldo Carvalho de Melo <acme@redhat.com> > Cc: Andi Kleen <ak@linux.intel.com> > Cc: Jiri Olsa <jolsa@kernel.org> > Cc: Ian Rogers <irogers@google.com> > Cc: Namhyung Kim <namhyung@kernel.org> > --- > .../scripts/python/bin/tasks-analyzer-record | 2 + > .../scripts/python/bin/tasks-analyzer-report | 3 + > tools/perf/scripts/python/tasks-analyzer.py | 838 ++++++++++++++++++ > 3 files changed, 843 insertions(+) > create mode 100755 tools/perf/scripts/python/bin/tasks-analyzer-record > create mode 100755 tools/perf/scripts/python/bin/tasks-analyzer-report > create mode 100755 tools/perf/scripts/python/tasks-analyzer.py > > diff --git a/tools/perf/scripts/python/bin/tasks-analyzer-record b/tools/perf/scripts/python/bin/tasks-analyzer-record > new file mode 100755 > index 000000000000..0f6b51bb2767 > --- /dev/null > +++ b/tools/perf/scripts/python/bin/tasks-analyzer-record > @@ -0,0 +1,2 @@ > +#!/bin/bash > +perf record -e sched:sched_switch -e sched:sched_migrate_task "$@" > diff --git a/tools/perf/scripts/python/bin/tasks-analyzer-report b/tools/perf/scripts/python/bin/tasks-analyzer-report > new file mode 100755 > index 000000000000..2da84ae03c0e > --- /dev/null > +++ b/tools/perf/scripts/python/bin/tasks-analyzer-report > @@ -0,0 +1,3 @@ > +#!/bin/bash > +# description: analyze timings of tasks > +perf script -s "$PERF_EXEC_PATH"/scripts/python/tasks-analyzer.py -- "$@" > diff --git a/tools/perf/scripts/python/tasks-analyzer.py b/tools/perf/scripts/python/tasks-analyzer.py > new file mode 100755 > index 000000000000..5188e373802b > --- /dev/null > +++ b/tools/perf/scripts/python/tasks-analyzer.py > @@ -0,0 +1,838 @@ > +# tasks-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 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"): > + """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(): > + fmt = "{{:>{}}}".format(LEN_SWITCHED_IN) > + fmt += " {{:>{}}}".format(LEN_SWITCHED_OUT) > + fmt += " {{:>{}}}".format(LEN_CPU) > + fmt += " {{:>{}}}".format(LEN_PID) > + fmt += " {{:>{}}}".format(LEN_TID) > + fmt += " {{:>{}}}".format(LEN_COMM) > + fmt += " {{:>{}}}".format(LEN_RUNTIME) > + fmt += " {{:>{}}}".format(LEN_OUT_IN) > + if args.extended_times: > + fmt += " {{:>{}}}".format(LEN_OUT_OUT) > + fmt += " {{:>{}}}".format(LEN_IN_IN) > + fmt += " {{:>{}}}".format(LEN_IN_OUT) > + return fmt > + > + > +def _fmt_body(): > + decimal_precision, time_precision = _prepare_fmt_precision() > + fmt = "{{}}{{:{}.{}f}}".format(LEN_SWITCHED_IN, decimal_precision) > + fmt += " {{:{}.{}f}}".format(LEN_SWITCHED_OUT, decimal_precision) > + fmt += " {{:{}d}}".format(LEN_CPU) > + fmt += " {{:{}d}}".format(LEN_PID) > + fmt += " {{}}{{:{}d}}{{}}".format(LEN_TID) > + fmt += " {{}}{{:>{}}}".format(LEN_COMM) > + fmt += " {{:{}.{}f}}".format(LEN_RUNTIME, time_precision) > + if args.extended_times: > + fmt += " {{:{}.{}f}}".format(LEN_OUT_IN, time_precision) > + fmt += " {{:{}.{}f}}".format(LEN_OUT_OUT, time_precision) > + fmt += " {{:{}.{}f}}".format(LEN_IN_IN, time_precision) > + fmt += " {{:{}.{}f}}{{}}".format(LEN_IN_OUT, time_precision) > + else: > + fmt += " {{:{}.{}f}}{{}}".format(LEN_OUT_IN, 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") > + print(fmt.format(*header)) > + > + > +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: > + print(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)) > + else: > + print(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)) > + > + > +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") > + > + > +def _argument_prepare_check(): > + global time_unit > + 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" > + > + > +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 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) > -- > 2.30.2 >
| |