| lists.openwall.net | lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC | |
|
Open Source and information security mailing list archives
| ||
|
Message-ID: <CAP-5=fV374SjiMQPsba3Tw2qJwtT8sXneRKAyqnEtCAhJ6FaUg@mail.gmail.com>
Date: Thu, 1 Dec 2022 16:05:15 -0800
From: Ian Rogers <irogers@...gle.com>
To: Petar Gligoric <petar.gligor@...il.com>
Cc: linux-kernel@...r.kernel.org, Hagen Paul Pfeifer <hagen@...u.net>,
Petar Gligoric <petar.gligoric@...de-schwarz.com>,
Arnaldo Carvalho de Melo <acme@...hat.com>,
Andi Kleen <ak@...ux.intel.com>, Jiri Olsa <jolsa@...nel.org>,
Namhyung Kim <namhyung@...nel.org>
Subject: Re: [PATCH 1/2] perf script: introduce task analyzer
On Thu, Dec 1, 2022 at 11:36 AM Petar Gligoric <petar.gligor@...il.com> wrote:
>
> From: Hagen Paul Pfeifer <hagen@...u.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@...u.net>
> Signed-off-by: Petar Gligoric <petar.gligoric@...de-schwarz.com>
> Cc: Arnaldo Carvalho de Melo <acme@...hat.com>
> Cc: Andi Kleen <ak@...ux.intel.com>
> Cc: Jiri Olsa <jolsa@...nel.org>
> Cc: Ian Rogers <irogers@...gle.com>
> Cc: Namhyung Kim <namhyung@...nel.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@...u.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
>
Powered by blists - more mailing lists