projects/linux·blob master · refs

934 lines · 33.2 KiB

1# task-analyzer.py - comprehensive perf tasks analysis
2# SPDX-License-Identifier: GPL-2.0
3# Copyright (c) 2022, Hagen Paul Pfeifer <[email protected]>
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
12from __future__ import print_function
13import sys
14import os
15import string
16import argparse
17import decimal
18
19
20sys.path.append(
21 os.environ["PERF_EXEC_PATH"] + "/scripts/python/Perf-Trace-Util/lib/Perf/Trace"
22)
23from perf_trace_context import *
24from 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
39LEN_SWITCHED_IN = len("9999999.999999999") # 17
40LEN_SWITCHED_OUT = len("9999999.999999999") # 17
41LEN_CPU = len("000")
42LEN_PID = len("maxvalue") # 8
43LEN_TID = len("maxvalue") # 8
44LEN_COMM = len("max-comms-length") # 16
45LEN_RUNTIME = len("999999.999") # 10
46# Support of 3.45 hours of timespans
47LEN_OUT_IN = len("99999999999.999") # 15
48LEN_OUT_OUT = len("99999999999.999") # 15
49LEN_IN_IN = len("99999999999.999") # 15
50LEN_IN_OUT = len("99999999999.999") # 15
51
52
53# py2/py3 compatibility layer, see PEP469
54try:
55 dict.iteritems
56except AttributeError:
57 # py3
58 def itervalues(d):
59 return iter(d.values())
60
61 def iteritems(d):
62 return iter(d.items())
63
64else:
65 # py2
66 def itervalues(d):
67 return d.itervalues()
68
69 def iteritems(d):
70 return d.iteritems()
71
72
73def _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
89def _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
178def time_uniter(unit):
179 picker = {
180 "s": 1,
181 "ms": 1e3,
182 "us": 1e6,
183 "ns": 1e9,
184 }
185 return picker[unit]
186
187
188def _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
218def _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
227def _mean(numbers):
228 return sum(numbers) / len(numbers)
229
230
231class 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
290class 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
531class 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
569def _task_id(pid, cpu):
570 """returns a "unique-enough" identifier, please do not change"""
571 return "{}-{}".format(pid, cpu)
572
573
574def _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
584def _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
601def _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
627def _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
637def _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
691def _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
700def _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
708def _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
716def _record_global(task):
717 """record all executed task, ordered by finish chronological"""
718 db["global"].append(task)
719 _record_cleanup(db["global"])
720
721
722def _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
752def _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
770def _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
777def _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
790def _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
812def _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
861def _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
889def _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
897def _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
905def trace_unhandled(event_name, context, event_fields_dict, perf_sample_dict):
906 pass
907
908
909def trace_begin():
910 _parse_args()
911 _check_color()
912 _init_db()
913 if not args.summary_only:
914 _print_header()
915
916def trace_end():
917 if args.summary or args.summary_extended or args.summary_only:
918 Summary().print()
919
920def 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)