tools/perf/scripts/python/task-analyzer.py

   1 # task-analyzer.py - comprehensive perf tasks analysis
   2 # SPDX-License-Identifier: GPL-2.0
   3 # Copyright (c) 2022, Hagen Paul Pfeifer <hagen@jauu.net>
   4 # Licensed under the terms of the GNU GPL License version 2
   5 #
   6 # Usage:
   7 #
   8 #     perf record -e sched:sched_switch -a -- sleep 10
   9 #     perf script report task-analyzer
  10 #
  11
  12 from __future__ import print_function
  13 import sys
  14 import os
  15 import string
  16 import argparse
  17 import decimal
  18
  19
  20 sys.path.append(
  21     os.environ["PERF_EXEC_PATH"] + "/scripts/python/Perf-Trace-Util/lib/Perf/Trace"
  22 )
  23 from perf_trace_context import *
  24 from Core import *
  25
  26 # Definition of possible ASCII color codes
  27 _COLORS = {
  28     "grey": "\033[90m",
  29     "red": "\033[91m",
  30     "green": "\033[92m",
  31     "yellow": "\033[93m",
  32     "blue": "\033[94m",
  33     "violet": "\033[95m",
  34     "reset": "\033[0m",
  35 }
  36
  37 # Columns will have a static size to align everything properly
  38 # Support of 116 days of active update with nano precision
  39 LEN_SWITCHED_IN = len("9999999.999999999")  # 17
  40 LEN_SWITCHED_OUT = len("9999999.999999999")  # 17
  41 LEN_CPU = len("000")
  42 LEN_PID = len("maxvalue")  # 8
  43 LEN_TID = len("maxvalue")  # 8
  44 LEN_COMM = len("max-comms-length")  # 16
  45 LEN_RUNTIME = len("999999.999")  # 10
  46 # Support of 3.45 hours of timespans
  47 LEN_OUT_IN = len("99999999999.999")  # 15
  48 LEN_OUT_OUT = len("99999999999.999")  # 15
  49 LEN_IN_IN = len("99999999999.999")  # 15
  50 LEN_IN_OUT = len("99999999999.999")  # 15
  51
  52
  53 # py2/py3 compatibility layer, see PEP469
  54 try:
  55     dict.iteritems
  56 except AttributeError:
  57     # py3
  58     def itervalues(d):
  59         return iter(d.values())
  60
  61     def iteritems(d):
  62         return iter(d.items())
  63
  64 else:
  65     # py2
  66     def itervalues(d):
  67         return d.itervalues()
  68
  69     def iteritems(d):
  70         return d.iteritems()
  71
  72
  73 def _check_color():
  74     global _COLORS
  75     """user enforced no-color or if stdout is no tty we disable colors"""
  76     if sys.stdout.isatty() and args.stdio_color != "never":
  77         return
  78     _COLORS = {
  79         "grey": "",
  80         "red": "",
  81         "green": "",
  82         "yellow": "",
  83         "blue": "",
  84         "violet": "",
  85         "reset": "",
  86     }
  87
  88
  89 def _parse_args():
  90     global args
  91     parser = argparse.ArgumentParser(description="Analyze tasks behavior")
  92     parser.add_argument(
  93         "--time-limit",
  94         default=[],
  95         help=
  96             "print tasks only in time[s] window e.g"
  97         " --time-limit 123.111:789.222(print all between 123.111 and 789.222)"
  98         " --time-limit 123: (print all from 123)"
  99         " --time-limit :456 (print all until incl. 456)",
 100     )
 101     parser.add_argument(
 102         "--summary", action="store_true", help="print addtional runtime information"
 103     )
 104     parser.add_argument(
 105         "--summary-only", action="store_true", help="print only summary without traces"
 106     )
 107     parser.add_argument(
 108         "--summary-extended",
 109         action="store_true",
 110         help="print the summary with additional information of max inter task times"
 111             " relative to the prev task",
 112     )
 113     parser.add_argument(
 114         "--ns", action="store_true", help="show timestamps in nanoseconds"
 115     )
 116     parser.add_argument(
 117         "--ms", action="store_true", help="show timestamps in milliseconds"
 118     )
 119     parser.add_argument(
 120         "--extended-times",
 121         action="store_true",
 122         help="Show the elapsed times between schedule in/schedule out"
 123             " of this task and the schedule in/schedule out of previous occurrence"
 124             " of the same task",
 125     )
 126     parser.add_argument(
 127         "--filter-tasks",
 128         default=[],
 129         help="filter out unneeded tasks by tid, pid or processname."
 130         " E.g --filter-task 1337,/sbin/init ",
 131     )
 132     parser.add_argument(
 133         "--limit-to-tasks",
 134         default=[],
 135         help="limit output to selected task by tid, pid, processname."
 136         " E.g --limit-to-tasks 1337,/sbin/init",
 137     )
 138     parser.add_argument(
 139         "--highlight-tasks",
 140         default="",
 141         help="colorize special tasks by their pid/tid/comm."
 142         " E.g. --highlight-tasks 1:red,mutt:yellow"
 143         " Colors available: red,grey,yellow,blue,violet,green",
 144     )
 145     parser.add_argument(
 146         "--rename-comms-by-tids",
 147         default="",
 148         help="rename task names by using tid (<tid>:<newname>,<tid>:<newname>)"
 149             " This option is handy for inexpressive processnames like python interpreted"
 150             " process. E.g --rename 1337:my-python-app",
 151     )
 152     parser.add_argument(
 153         "--stdio-color",
 154         default="auto",
 155         choices=["always", "never", "auto"],
 156         help="always, never or auto, allowing configuring color output"
 157             " via the command line",
 158     )
 159     parser.add_argument(
 160         "--csv",
 161         default="",
 162         help="Write trace to file selected by user. Options, like --ns or --extended"
 163             "-times are used.",
 164     )
 165     parser.add_argument(
 166         "--csv-summary",
 167         default="",
 168         help="Write summary to file selected by user. Options, like --ns or"
 169             " --summary-extended are used.",
 170     )
 171     args = parser.parse_args()
 172     args.tid_renames = dict()
 173
 174     _argument_filter_sanity_check()
 175     _argument_prepare_check()
 176
 177
 178 def time_uniter(unit):
 179     picker = {
 180         "s": 1,
 181         "ms": 1e3,
 182         "us": 1e6,
 183         "ns": 1e9,
 184     }
 185     return picker[unit]
 186
 187
 188 def _init_db():
 189     global db
 190     db = dict()
 191     db["running"] = dict()
 192     db["cpu"] = dict()
 193     db["tid"] = dict()
 194     db["global"] = []
 195     if args.summary or args.summary_extended or args.summary_only:
 196         db["task_info"] = dict()
 197         db["runtime_info"] = dict()
 198         # min values for summary depending on the header
 199         db["task_info"]["pid"] = len("PID")
 200         db["task_info"]["tid"] = len("TID")
 201         db["task_info"]["comm"] = len("Comm")
 202         db["runtime_info"]["runs"] = len("Runs")
 203         db["runtime_info"]["acc"] = len("Accumulated")
 204         db["runtime_info"]["max"] = len("Max")
 205         db["runtime_info"]["max_at"] = len("Max At")
 206         db["runtime_info"]["min"] = len("Min")
 207         db["runtime_info"]["mean"] = len("Mean")
 208         db["runtime_info"]["median"] = len("Median")
 209         if args.summary_extended:
 210             db["inter_times"] = dict()
 211             db["inter_times"]["out_in"] = len("Out-In")
 212             db["inter_times"]["inter_at"] = len("At")
 213             db["inter_times"]["out_out"] = len("Out-Out")
 214             db["inter_times"]["in_in"] = len("In-In")
 215             db["inter_times"]["in_out"] = len("In-Out")
 216
 217
 218 def _median(numbers):
 219     """phython3 hat statistics module - we have nothing"""
 220     n = len(numbers)
 221     index = n // 2
 222     if n % 2:
 223         return sorted(numbers)[index]
 224     return sum(sorted(numbers)[index - 1 : index + 1]) / 2
 225
 226
 227 def _mean(numbers):
 228     return sum(numbers) / len(numbers)
 229
 230
 231 class Timespans(object):
 232     """
 233     The elapsed time between two occurrences of the same task is being tracked with the
 234     help of this class. There are 4 of those Timespans Out-Out, In-Out, Out-In and
 235     In-In.
 236     The first half of the name signals the first time point of the
 237     first task. The second half of the name represents the second
 238     timepoint of the second task.
 239     """
 240
 241     def __init__(self):
 242         self._last_start = None
 243         self._last_finish = None
 244         self.out_out = -1
 245         self.in_out = -1
 246         self.out_in = -1
 247         self.in_in = -1
 248         if args.summary_extended:
 249             self._time_in = -1
 250             self.max_out_in = -1
 251             self.max_at = -1
 252             self.max_in_out = -1
 253             self.max_in_in = -1
 254             self.max_out_out = -1
 255
 256     def feed(self, task):
 257         """
 258         Called for every recorded trace event to find process pair and calculate the
 259         task timespans. Chronological ordering, feed does not do reordering
 260         """
 261         if not self._last_finish:
 262             self._last_start = task.time_in(time_unit)
 263             self._last_finish = task.time_out(time_unit)
 264             return
 265         self._time_in = task.time_in()
 266         time_in = task.time_in(time_unit)
 267         time_out = task.time_out(time_unit)
 268         self.in_in = time_in - self._last_start
 269         self.out_in = time_in - self._last_finish
 270         self.in_out = time_out - self._last_start
 271         self.out_out = time_out - self._last_finish
 272         if args.summary_extended:
 273             self._update_max_entries()
 274         self._last_finish = task.time_out(time_unit)
 275         self._last_start = task.time_in(time_unit)
 276
 277     def _update_max_entries(self):
 278         if self.in_in > self.max_in_in:
 279             self.max_in_in = self.in_in
 280         if self.out_out > self.max_out_out:
 281             self.max_out_out = self.out_out
 282         if self.in_out > self.max_in_out:
 283             self.max_in_out = self.in_out
 284         if self.out_in > self.max_out_in:
 285             self.max_out_in = self.out_in
 286             self.max_at = self._time_in
 287
 288
 289
 290 class Summary(object):
 291     """
 292     Primary instance for calculating the summary output. Processes the whole trace to
 293     find and memorize relevant data such as mean, max et cetera. This instance handles
 294     dynamic alignment aspects for summary output.
 295     """
 296
 297     def __init__(self):
 298         self._body = []
 299
 300     class AlignmentHelper:
 301         """
 302         Used to calculated the alignment for the output of the summary.
 303         """
 304         def __init__(self, pid, tid, comm, runs, acc, mean,
 305                     median, min, max, max_at):
 306             self.pid = pid
 307             self.tid = tid
 308             self.comm = comm
 309             self.runs = runs
 310             self.acc = acc
 311             self.mean = mean
 312             self.median = median
 313             self.min = min
 314             self.max = max
 315             self.max_at = max_at
 316             if args.summary_extended:
 317                 self.out_in = None
 318                 self.inter_at = None
 319                 self.out_out = None
 320                 self.in_in = None
 321                 self.in_out = None
 322
 323     def _print_header(self):
 324         '''
 325         Output is trimmed in _format_stats thus additional adjustment in the header
 326         is needed, depending on the choice of timeunit. The adjustment corresponds
 327         to the amount of column titles being adjusted in _column_titles.
 328         '''
 329         decimal_precision = 6 if not args.ns else 9
 330         fmt = " {{:^{}}}".format(sum(db["task_info"].values()))
 331         fmt += " {{:^{}}}".format(
 332             sum(db["runtime_info"].values()) - 2 * decimal_precision
 333             )
 334         _header = ("Task Information", "Runtime Information")
 335
 336         if args.summary_extended:
 337             fmt += " {{:^{}}}".format(
 338                 sum(db["inter_times"].values()) - 4 * decimal_precision
 339                 )
 340             _header += ("Max Inter Task Times",)
 341         fd_sum.write(fmt.format(*_header) +  "\n")
 342
 343     def _column_titles(self):
 344         """
 345         Cells are being processed and displayed in different way so an alignment adjust
 346         is implemented depeding on the choice of the timeunit. The positions of the max
 347         values are being displayed in grey. Thus in their format two additional {},
 348         are placed for color set and reset.
 349         """
 350         separator, fix_csv_align = _prepare_fmt_sep()
 351         decimal_precision, time_precision = _prepare_fmt_precision()
 352         fmt = "{{:>{}}}".format(db["task_info"]["pid"] * fix_csv_align)
 353         fmt += "{}{{:>{}}}".format(separator, db["task_info"]["tid"] * fix_csv_align)
 354         fmt += "{}{{:>{}}}".format(separator, db["task_info"]["comm"] * fix_csv_align)
 355         fmt += "{}{{:>{}}}".format(separator, db["runtime_info"]["runs"] * fix_csv_align)
 356         fmt += "{}{{:>{}}}".format(separator, db["runtime_info"]["acc"] * fix_csv_align)
 357         fmt += "{}{{:>{}}}".format(separator, db["runtime_info"]["mean"] * fix_csv_align)
 358         fmt += "{}{{:>{}}}".format(
 359             separator, db["runtime_info"]["median"] * fix_csv_align
 360         )
 361         fmt += "{}{{:>{}}}".format(
 362             separator, (db["runtime_info"]["min"] - decimal_precision) * fix_csv_align
 363         )
 364         fmt += "{}{{:>{}}}".format(
 365             separator, (db["runtime_info"]["max"] - decimal_precision) * fix_csv_align
 366         )
 367         fmt += "{}{{}}{{:>{}}}{{}}".format(
 368             separator, (db["runtime_info"]["max_at"] - time_precision) * fix_csv_align
 369         )
 370
 371         column_titles = ("PID", "TID", "Comm")
 372         column_titles += ("Runs", "Accumulated", "Mean", "Median", "Min", "Max")
 373         column_titles += (_COLORS["grey"], "Max At", _COLORS["reset"])
 374
 375         if args.summary_extended:
 376             fmt += "{}{{:>{}}}".format(
 377                 separator,
 378                 (db["inter_times"]["out_in"] - decimal_precision) * fix_csv_align
 379             )
 380             fmt += "{}{{}}{{:>{}}}{{}}".format(
 381                 separator,
 382                 (db["inter_times"]["inter_at"] - time_precision) * fix_csv_align
 383             )
 384             fmt += "{}{{:>{}}}".format(
 385                 separator,
 386                 (db["inter_times"]["out_out"] - decimal_precision) * fix_csv_align
 387             )
 388             fmt += "{}{{:>{}}}".format(
 389                 separator,
 390                 (db["inter_times"]["in_in"] - decimal_precision) * fix_csv_align
 391             )
 392             fmt += "{}{{:>{}}}".format(
 393                 separator,
 394                 (db["inter_times"]["in_out"] - decimal_precision) * fix_csv_align
 395             )
 396
 397             column_titles += ("Out-In", _COLORS["grey"], "Max At", _COLORS["reset"],
 398                         "Out-Out", "In-In", "In-Out")
 399
 400         fd_sum.write(fmt.format(*column_titles) + "\n")
 401
 402
 403     def _task_stats(self):
 404         """calculates the stats of every task and constructs the printable summary"""
 405         for tid in sorted(db["tid"]):
 406             color_one_sample = _COLORS["grey"]
 407             color_reset = _COLORS["reset"]
 408             no_executed = 0
 409             runtimes = []
 410             time_in = []
 411             timespans = Timespans()
 412             for task in db["tid"][tid]:
 413                 pid = task.pid
 414                 comm = task.comm
 415                 no_executed += 1
 416                 runtimes.append(task.runtime(time_unit))
 417                 time_in.append(task.time_in())
 418                 timespans.feed(task)
 419             if len(runtimes) > 1:
 420                 color_one_sample = ""
 421                 color_reset = ""
 422             time_max = max(runtimes)
 423             time_min = min(runtimes)
 424             max_at = time_in[runtimes.index(max(runtimes))]
 425
 426             # The size of the decimal after sum,mean and median varies, thus we cut
 427             # the decimal number, by rounding it. It has no impact on the output,
 428             # because we have a precision of the decimal points at the output.
 429             time_sum = round(sum(runtimes), 3)
 430             time_mean = round(_mean(runtimes), 3)
 431             time_median = round(_median(runtimes), 3)
 432
 433             align_helper = self.AlignmentHelper(pid, tid, comm, no_executed, time_sum,
 434                                     time_mean, time_median, time_min, time_max, max_at)
 435             self._body.append([pid, tid, comm, no_executed, time_sum, color_one_sample,
 436                                 time_mean, time_median, time_min, time_max,
 437                                 _COLORS["grey"], max_at, _COLORS["reset"], color_reset])
 438             if args.summary_extended:
 439                 self._body[-1].extend([timespans.max_out_in,
 440                                 _COLORS["grey"], timespans.max_at,
 441                                 _COLORS["reset"], timespans.max_out_out,
 442                                 timespans.max_in_in,
 443                                 timespans.max_in_out])
 444                 align_helper.out_in = timespans.max_out_in
 445                 align_helper.inter_at = timespans.max_at
 446                 align_helper.out_out = timespans.max_out_out
 447                 align_helper.in_in = timespans.max_in_in
 448                 align_helper.in_out = timespans.max_in_out
 449             self._calc_alignments_summary(align_helper)
 450
 451     def _format_stats(self):
 452         separator, fix_csv_align = _prepare_fmt_sep()
 453         decimal_precision, time_precision = _prepare_fmt_precision()
 454         len_pid = db["task_info"]["pid"] * fix_csv_align
 455         len_tid = db["task_info"]["tid"] * fix_csv_align
 456         len_comm = db["task_info"]["comm"] * fix_csv_align
 457         len_runs = db["runtime_info"]["runs"] * fix_csv_align
 458         len_acc = db["runtime_info"]["acc"] * fix_csv_align
 459         len_mean = db["runtime_info"]["mean"] * fix_csv_align
 460         len_median = db["runtime_info"]["median"] * fix_csv_align
 461         len_min = (db["runtime_info"]["min"] - decimal_precision) * fix_csv_align
 462         len_max = (db["runtime_info"]["max"] - decimal_precision) * fix_csv_align
 463         len_max_at = (db["runtime_info"]["max_at"] - time_precision) * fix_csv_align
 464         if args.summary_extended:
 465             len_out_in = (
 466                 db["inter_times"]["out_in"] - decimal_precision
 467             ) * fix_csv_align
 468             len_inter_at = (
 469                 db["inter_times"]["inter_at"] - time_precision
 470             ) * fix_csv_align
 471             len_out_out = (
 472                 db["inter_times"]["out_out"] - decimal_precision
 473             ) * fix_csv_align
 474             len_in_in = (db["inter_times"]["in_in"] - decimal_precision) * fix_csv_align
 475             len_in_out = (
 476                 db["inter_times"]["in_out"] - decimal_precision
 477             ) * fix_csv_align
 478
 479         fmt = "{{:{}d}}".format(len_pid)
 480         fmt += "{}{{:{}d}}".format(separator, len_tid)
 481         fmt += "{}{{:>{}}}".format(separator, len_comm)
 482         fmt += "{}{{:{}d}}".format(separator, len_runs)
 483         fmt += "{}{{:{}.{}f}}".format(separator, len_acc, time_precision)
 484         fmt += "{}{{}}{{:{}.{}f}}".format(separator, len_mean, time_precision)
 485         fmt += "{}{{:{}.{}f}}".format(separator, len_median, time_precision)
 486         fmt += "{}{{:{}.{}f}}".format(separator, len_min, time_precision)
 487         fmt += "{}{{:{}.{}f}}".format(separator, len_max, time_precision)
 488         fmt += "{}{{}}{{:{}.{}f}}{{}}{{}}".format(
 489             separator, len_max_at, decimal_precision
 490         )
 491         if args.summary_extended:
 492             fmt += "{}{{:{}.{}f}}".format(separator, len_out_in, time_precision)
 493             fmt += "{}{{}}{{:{}.{}f}}{{}}".format(
 494                 separator, len_inter_at, decimal_precision
 495             )
 496             fmt += "{}{{:{}.{}f}}".format(separator, len_out_out, time_precision)
 497             fmt += "{}{{:{}.{}f}}".format(separator, len_in_in, time_precision)
 498             fmt += "{}{{:{}.{}f}}".format(separator, len_in_out, time_precision)
 499         return fmt
 500
 501
 502     def _calc_alignments_summary(self, align_helper):
 503         # Length is being cut in 3 groups so that further addition is easier to handle.
 504         # The length of every argument from the alignment helper is being checked if it
 505         # is longer than the longest until now. In that case the length is being saved.
 506         for key in db["task_info"]:
 507             if len(str(getattr(align_helper, key))) > db["task_info"][key]:
 508                 db["task_info"][key] = len(str(getattr(align_helper, key)))
 509         for key in db["runtime_info"]:
 510             if len(str(getattr(align_helper, key))) > db["runtime_info"][key]:
 511                 db["runtime_info"][key] = len(str(getattr(align_helper, key)))
 512         if args.summary_extended:
 513             for key in db["inter_times"]:
 514                 if len(str(getattr(align_helper, key))) > db["inter_times"][key]:
 515                     db["inter_times"][key] = len(str(getattr(align_helper, key)))
 516
 517
 518     def print(self):
 519         self._task_stats()
 520         fmt = self._format_stats()
 521
 522         if not args.csv_summary:
 523             print("\nSummary")
 524             self._print_header()
 525         self._column_titles()
 526         for i in range(len(self._body)):
 527             fd_sum.write(fmt.format(*tuple(self._body[i])) + "\n")
 528
 529
 530
 531 class Task(object):
 532     """ The class is used to handle the information of a given task."""
 533
 534     def __init__(self, id, tid, cpu, comm):
 535         self.id = id
 536         self.tid = tid
 537         self.cpu = cpu
 538         self.comm = comm
 539         self.pid = None
 540         self._time_in = None
 541         self._time_out = None
 542
 543     def schedule_in_at(self, time):
 544         """set the time where the task was scheduled in"""
 545         self._time_in = time
 546
 547     def schedule_out_at(self, time):
 548         """set the time where the task was scheduled out"""
 549         self._time_out = time
 550
 551     def time_out(self, unit="s"):
 552         """return time where a given task was scheduled out"""
 553         factor = time_uniter(unit)
 554         return self._time_out * decimal.Decimal(factor)
 555
 556     def time_in(self, unit="s"):
 557         """return time where a given task was scheduled in"""
 558         factor = time_uniter(unit)
 559         return self._time_in * decimal.Decimal(factor)
 560
 561     def runtime(self, unit="us"):
 562         factor = time_uniter(unit)
 563         return (self._time_out - self._time_in) * decimal.Decimal(factor)
 564
 565     def update_pid(self, pid):
 566         self.pid = pid
 567
 568
 569 def _task_id(pid, cpu):
 570     """returns a "unique-enough" identifier, please do not change"""
 571     return "{}-{}".format(pid, cpu)
 572
 573
 574 def _filter_non_printable(unfiltered):
 575     """comm names may contain loony chars like '\x00000'"""
 576     filtered = ""
 577     for char in unfiltered:
 578         if char not in string.printable:
 579             continue
 580         filtered += char
 581     return filtered
 582
 583
 584 def _fmt_header():
 585     separator, fix_csv_align = _prepare_fmt_sep()
 586     fmt = "{{:>{}}}".format(LEN_SWITCHED_IN*fix_csv_align)
 587     fmt += "{}{{:>{}}}".format(separator, LEN_SWITCHED_OUT*fix_csv_align)
 588     fmt += "{}{{:>{}}}".format(separator, LEN_CPU*fix_csv_align)
 589     fmt += "{}{{:>{}}}".format(separator, LEN_PID*fix_csv_align)
 590     fmt += "{}{{:>{}}}".format(separator, LEN_TID*fix_csv_align)
 591     fmt += "{}{{:>{}}}".format(separator, LEN_COMM*fix_csv_align)
 592     fmt += "{}{{:>{}}}".format(separator, LEN_RUNTIME*fix_csv_align)
 593     fmt += "{}{{:>{}}}".format(separator, LEN_OUT_IN*fix_csv_align)
 594     if args.extended_times:
 595         fmt += "{}{{:>{}}}".format(separator, LEN_OUT_OUT*fix_csv_align)
 596         fmt += "{}{{:>{}}}".format(separator, LEN_IN_IN*fix_csv_align)
 597         fmt += "{}{{:>{}}}".format(separator, LEN_IN_OUT*fix_csv_align)
 598     return fmt
 599
 600
 601 def _fmt_body():
 602     separator, fix_csv_align = _prepare_fmt_sep()
 603     decimal_precision, time_precision = _prepare_fmt_precision()
 604     fmt = "{{}}{{:{}.{}f}}".format(LEN_SWITCHED_IN*fix_csv_align, decimal_precision)
 605     fmt += "{}{{:{}.{}f}}".format(
 606         separator, LEN_SWITCHED_OUT*fix_csv_align, decimal_precision
 607     )
 608     fmt += "{}{{:{}d}}".format(separator, LEN_CPU*fix_csv_align)
 609     fmt += "{}{{:{}d}}".format(separator, LEN_PID*fix_csv_align)
 610     fmt += "{}{{}}{{:{}d}}{{}}".format(separator, LEN_TID*fix_csv_align)
 611     fmt += "{}{{}}{{:>{}}}".format(separator, LEN_COMM*fix_csv_align)
 612     fmt += "{}{{:{}.{}f}}".format(separator, LEN_RUNTIME*fix_csv_align, time_precision)
 613     if args.extended_times:
 614         fmt += "{}{{:{}.{}f}}".format(separator, LEN_OUT_IN*fix_csv_align, time_precision)
 615         fmt += "{}{{:{}.{}f}}".format(separator, LEN_OUT_OUT*fix_csv_align, time_precision)
 616         fmt += "{}{{:{}.{}f}}".format(separator, LEN_IN_IN*fix_csv_align, time_precision)
 617         fmt += "{}{{:{}.{}f}}{{}}".format(
 618             separator, LEN_IN_OUT*fix_csv_align, time_precision
 619         )
 620     else:
 621         fmt += "{}{{:{}.{}f}}{{}}".format(
 622             separator, LEN_OUT_IN*fix_csv_align, time_precision
 623         )
 624     return fmt
 625
 626
 627 def _print_header():
 628     fmt = _fmt_header()
 629     header = ("Switched-In", "Switched-Out", "CPU", "PID", "TID", "Comm", "Runtime",
 630             "Time Out-In")
 631     if args.extended_times:
 632         header += ("Time Out-Out", "Time In-In", "Time In-Out")
 633     fd_task.write(fmt.format(*header) + "\n")
 634
 635
 636
 637 def _print_task_finish(task):
 638     """calculating every entry of a row and printing it immediately"""
 639     c_row_set = ""
 640     c_row_reset = ""
 641     out_in = -1
 642     out_out = -1
 643     in_in = -1
 644     in_out = -1
 645     fmt = _fmt_body()
 646     # depending on user provided highlight option we change the color
 647     # for particular tasks
 648     if str(task.tid) in args.highlight_tasks_map:
 649         c_row_set = _COLORS[args.highlight_tasks_map[str(task.tid)]]
 650         c_row_reset = _COLORS["reset"]
 651     if task.comm in args.highlight_tasks_map:
 652         c_row_set = _COLORS[args.highlight_tasks_map[task.comm]]
 653         c_row_reset = _COLORS["reset"]
 654     # grey-out entries if PID == TID, they
 655     # are identical, no threaded model so the
 656     # thread id (tid) do not matter
 657     c_tid_set = ""
 658     c_tid_reset = ""
 659     if task.pid == task.tid:
 660         c_tid_set = _COLORS["grey"]
 661         c_tid_reset = _COLORS["reset"]
 662     if task.tid in db["tid"]:
 663         # get last task of tid
 664         last_tid_task = db["tid"][task.tid][-1]
 665         # feed the timespan calculate, last in tid db
 666         # and second the current one
 667         timespan_gap_tid = Timespans()
 668         timespan_gap_tid.feed(last_tid_task)
 669         timespan_gap_tid.feed(task)
 670         out_in = timespan_gap_tid.out_in
 671         out_out = timespan_gap_tid.out_out
 672         in_in = timespan_gap_tid.in_in
 673         in_out = timespan_gap_tid.in_out
 674
 675
 676     if args.extended_times:
 677         line_out = fmt.format(c_row_set, task.time_in(), task.time_out(), task.cpu,
 678                         task.pid, c_tid_set, task.tid, c_tid_reset, c_row_set, task.comm,
 679                         task.runtime(time_unit), out_in, out_out, in_in, in_out,
 680                         c_row_reset) + "\n"
 681     else:
 682         line_out = fmt.format(c_row_set, task.time_in(), task.time_out(), task.cpu,
 683                         task.pid, c_tid_set, task.tid, c_tid_reset, c_row_set, task.comm,
 684                         task.runtime(time_unit), out_in, c_row_reset) + "\n"
 685     try:
 686         fd_task.write(line_out)
 687     except(IOError):
 688         # don't mangle the output if user SIGINT this script
 689         sys.exit()
 690
 691 def _record_cleanup(_list):
 692     """
 693     no need to store more then one element if --summarize
 694     is not enabled
 695     """
 696     if not args.summary and len(_list) > 1:
 697         _list = _list[len(_list) - 1 :]
 698
 699
 700 def _record_by_tid(task):
 701     tid = task.tid
 702     if tid not in db["tid"]:
 703         db["tid"][tid] = []
 704     db["tid"][tid].append(task)
 705     _record_cleanup(db["tid"][tid])
 706
 707
 708 def _record_by_cpu(task):
 709     cpu = task.cpu
 710     if cpu not in db["cpu"]:
 711         db["cpu"][cpu] = []
 712     db["cpu"][cpu].append(task)
 713     _record_cleanup(db["cpu"][cpu])
 714
 715
 716 def _record_global(task):
 717     """record all executed task, ordered by finish chronological"""
 718     db["global"].append(task)
 719     _record_cleanup(db["global"])
 720
 721
 722 def _handle_task_finish(tid, cpu, time, perf_sample_dict):
 723     if tid == 0:
 724         return
 725     _id = _task_id(tid, cpu)
 726     if _id not in db["running"]:
 727         # may happen, if we missed the switch to
 728         # event. Seen in combination with --exclude-perf
 729         # where the start is filtered out, but not the
 730         # switched in. Probably a bug in exclude-perf
 731         # option.
 732         return
 733     task = db["running"][_id]
 734     task.schedule_out_at(time)
 735
 736     # record tid, during schedule in the tid
 737     # is not available, update now
 738     pid = int(perf_sample_dict["sample"]["pid"])
 739
 740     task.update_pid(pid)
 741     del db["running"][_id]
 742
 743     # print only tasks which are not being filtered and no print of trace
 744     # for summary only, but record every task.
 745     if not _limit_filtered(tid, pid, task.comm) and not args.summary_only:
 746         _print_task_finish(task)
 747     _record_by_tid(task)
 748     _record_by_cpu(task)
 749     _record_global(task)
 750
 751
 752 def _handle_task_start(tid, cpu, comm, time):
 753     if tid == 0:
 754         return
 755     if tid in args.tid_renames:
 756         comm = args.tid_renames[tid]
 757     _id = _task_id(tid, cpu)
 758     if _id in db["running"]:
 759         # handle corner cases where already running tasks
 760         # are switched-to again - saw this via --exclude-perf
 761         # recorded traces. We simple ignore this "second start"
 762         # event.
 763         return
 764     assert _id not in db["running"]
 765     task = Task(_id, tid, cpu, comm)
 766     task.schedule_in_at(time)
 767     db["running"][_id] = task
 768
 769
 770 def _time_to_internal(time_ns):
 771     """
 772     To prevent float rounding errors we use Decimal internally
 773     """
 774     return decimal.Decimal(time_ns) / decimal.Decimal(1e9)
 775
 776
 777 def _limit_filtered(tid, pid, comm):
 778     if args.filter_tasks:
 779         if str(tid) in args.filter_tasks or comm in args.filter_tasks:
 780             return True
 781         else:
 782             return False
 783     if args.limit_to_tasks:
 784         if str(tid) in args.limit_to_tasks or comm in args.limit_to_tasks:
 785             return False
 786         else:
 787             return True
 788
 789
 790 def _argument_filter_sanity_check():
 791     if args.limit_to_tasks and args.filter_tasks:
 792         sys.exit("Error: Filter and Limit at the same time active.")
 793     if args.extended_times and args.summary_only:
 794         sys.exit("Error: Summary only and extended times active.")
 795     if args.time_limit and ":" not in args.time_limit:
 796         sys.exit(
 797             "Error: No bound set for time limit. Please set bound by ':' e.g :123."
 798         )
 799     if args.time_limit and (args.summary or args.summary_only or args.summary_extended):
 800         sys.exit("Error: Cannot set time limit and print summary")
 801     if args.csv_summary:
 802         args.summary = True
 803         if args.csv == args.csv_summary:
 804             sys.exit("Error: Chosen files for csv and csv summary are the same")
 805     if args.csv and (args.summary_extended or args.summary) and not args.csv_summary:
 806         sys.exit("Error: No file chosen to write summary to. Choose with --csv-summary "
 807         "<file>")
 808     if args.csv and args.summary_only:
 809         sys.exit("Error: --csv chosen and --summary-only. Standard task would not be"
 810             "written to csv file.")
 811
 812 def _argument_prepare_check():
 813     global time_unit, fd_task, fd_sum
 814     if args.filter_tasks:
 815         args.filter_tasks = args.filter_tasks.split(",")
 816     if args.limit_to_tasks:
 817         args.limit_to_tasks = args.limit_to_tasks.split(",")
 818     if args.time_limit:
 819         args.time_limit = args.time_limit.split(":")
 820     for rename_tuple in args.rename_comms_by_tids.split(","):
 821         tid_name = rename_tuple.split(":")
 822         if len(tid_name) != 2:
 823             continue
 824         args.tid_renames[int(tid_name[0])] = tid_name[1]
 825     args.highlight_tasks_map = dict()
 826     for highlight_tasks_tuple in args.highlight_tasks.split(","):
 827         tasks_color_map = highlight_tasks_tuple.split(":")
 828         # default highlight color to red if no color set by user
 829         if len(tasks_color_map) == 1:
 830             tasks_color_map.append("red")
 831         if args.highlight_tasks and tasks_color_map[1].lower() not in _COLORS:
 832             sys.exit(
 833                 "Error: Color not defined, please choose from grey,red,green,yellow,blue,"
 834                 "violet"
 835             )
 836         if len(tasks_color_map) != 2:
 837             continue
 838         args.highlight_tasks_map[tasks_color_map[0]] = tasks_color_map[1]
 839     time_unit = "us"
 840     if args.ns:
 841         time_unit = "ns"
 842     elif args.ms:
 843         time_unit = "ms"
 844
 845
 846     fd_task = sys.stdout
 847     if args.csv:
 848         args.stdio_color = "never"
 849         fd_task = open(args.csv, "w")
 850         print("generating csv at",args.csv,)
 851
 852     fd_sum = sys.stdout
 853     if args.csv_summary:
 854         args.stdio_color = "never"
 855         fd_sum = open(args.csv_summary, "w")
 856         print("generating csv summary at",args.csv_summary)
 857         if not args.csv:
 858             args.summary_only = True
 859
 860
 861 def _is_within_timelimit(time):
 862     """
 863     Check if a time limit was given by parameter, if so ignore the rest. If not,
 864     process the recorded trace in its entirety.
 865     """
 866     if not args.time_limit:
 867         return True
 868     lower_time_limit = args.time_limit[0]
 869     upper_time_limit = args.time_limit[1]
 870     # check for upper limit
 871     if upper_time_limit == "":
 872         if time >= decimal.Decimal(lower_time_limit):
 873             return True
 874     # check for lower limit
 875     if lower_time_limit == "":
 876         if time <= decimal.Decimal(upper_time_limit):
 877             return True
 878         # quit if time exceeds upper limit. Good for big datasets
 879         else:
 880             quit()
 881     if lower_time_limit != "" and upper_time_limit != "":
 882         if (time >= decimal.Decimal(lower_time_limit) and
 883             time <= decimal.Decimal(upper_time_limit)):
 884             return True
 885         # quit if time exceeds upper limit. Good for big datasets
 886         elif time > decimal.Decimal(upper_time_limit):
 887             quit()
 888
 889 def _prepare_fmt_precision():
 890     decimal_precision = 6
 891     time_precision = 3
 892     if args.ns:
 893      decimal_precision = 9
 894      time_precision = 0
 895     return decimal_precision, time_precision
 896
 897 def _prepare_fmt_sep():
 898     separator = " "
 899     fix_csv_align = 1
 900     if args.csv or args.csv_summary:
 901         separator = ";"
 902         fix_csv_align = 0
 903     return separator, fix_csv_align
 904
 905 def trace_unhandled(event_name, context, event_fields_dict, perf_sample_dict):
 906     pass
 907
 908
 909 def trace_begin():
 910     _parse_args()
 911     _check_color()
 912     _init_db()
 913     if not args.summary_only:
 914         _print_header()
 915
 916 def trace_end():
 917     if args.summary or args.summary_extended or args.summary_only:
 918         Summary().print()
 919
 920 def sched__sched_switch(event_name, context, common_cpu, common_secs, common_nsecs,
 921                         common_pid, common_comm, common_callchain, prev_comm,
 922                         prev_pid, prev_prio, prev_state, next_comm, next_pid,
 923                         next_prio, perf_sample_dict):
 924     # ignore common_secs & common_nsecs cause we need
 925     # high res timestamp anyway, using the raw value is
 926     # faster
 927     time = _time_to_internal(perf_sample_dict["sample"]["time"])
 928     if not _is_within_timelimit(time):
 929         # user specific --time-limit a:b set
 930         return
 931
 932     next_comm = _filter_non_printable(next_comm)
 933     _handle_task_finish(prev_pid, common_cpu, time, perf_sample_dict)
 934     _handle_task_start(next_pid, common_cpu, next_comm, time)