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) 935