emdbg.analyze.priority

  1# Copyright (c) 2023, Auterion AG
  2# SPDX-License-Identifier: BSD-3-Clause
  3
  4"""
  5You can generate semaphore boosts logs either at runtime using the
  6`emdbg.patch.set.semaphore_boostlog` patch, or using the
  7`px4_calltrace_semaphore_boosts` command of the `emdbg.bench.skynode` module
  8at debug time.
  9
 10
 11## Command Line Interface
 12
 13You can summarize boost logs:
 14
 15```sh
 16python3 -m emdbg.analyze.priority log_semaphore_boosts.txt
 17```
 18
 19You can also generate a callgraph with boost operations:
 20
 21```sh
 22python3 -m emdbg.analyze.callgraph log_semaphore_boosts.txt --svg --type Semaphore
 23```
 24"""
 25
 26from __future__ import annotations
 27import re
 28from pathlib import Path
 29import statistics
 30import itertools
 31from collections import defaultdict
 32from ..debug.px4.utils import format_table
 33from .utils import read_gdb_log
 34
 35class _BoostOperation:
 36    PATTERN = re.compile(r"L(\d+) +(\d+)us> +(0x[0-9a-f]+|<opti-out>): +(.*?) +(\d+) +([\\/_]+) +(\d+) *(.*)")
 37
 38    def __init__(self, description):
 39        self.is_valid = False
 40        if match := self.PATTERN.search(description):
 41            self.line = int(match.group(1))
 42            self.uptime = int(match.group(2))
 43            try:
 44                self.semaphore = int(match.group(3), 16)
 45            except:
 46                self.semaphore = None
 47            self.task = match.group(4)
 48            self.prio_from = int(match.group(5))
 49            self.operation = match.group(6)
 50            self.prio_to = int(match.group(7))
 51            self.reason = None if not match.group(8) else match.group(8)
 52            self.is_valid = True
 53
 54    def __repr__(self) -> str:
 55        return f"{self.task} {self.prio_from} {self.operation} {self.prio_to}"
 56
 57
 58def summarize_semaphore_boostlog(logfile: Path) -> str:
 59    """
 60    Analyze a boost log and create a statistical summary and return it.
 61
 62    :param logfile: The boostlog file to analyze
 63    :return: A formatted string containing the analysis.
 64    """
 65    output = []
 66
 67    ops = []
 68    for line in read_gdb_log(logfile).splitlines():
 69        op = _BoostOperation(line)
 70        if op.is_valid:
 71            ops.append(op)
 72        # else:
 73        #     print(line)
 74    if not ops: return "No task boosts found!"
 75    ops.sort(key=lambda o: o.uptime)
 76
 77
 78    uptime = ops[-1].uptime
 79    sample_time = max(o.uptime for o in ops) - min(o.uptime for o in ops)
 80    output.append(f"Uptime: {uptime/1e6:.1f}s = {uptime/6e7:.1f}min")
 81    output.append(f"Sample time: {sample_time/1e6:.1f}s = {sample_time/6e7:.1f}min")
 82
 83    # Print summary statistics
 84    prios = []
 85    def _mean(values):
 86        return int((statistics.fmean(values) if len(values) else 0) / 1e3)
 87    def _stdev(values):
 88        if len(values) >= 2: return int(statistics.stdev(values) / 1e3)
 89        return values[0] if len(values) else 0
 90
 91    diffs = [n.uptime - p.uptime for p,n in itertools.pairwise(ops)]
 92    prios.append(["All", len(ops), _mean(diffs), _stdev(diffs)])
 93
 94    boost_up = [op for op in ops if op.operation == "_/"]
 95    diffs_up = [n.uptime - p.uptime for p,n in itertools.pairwise(boost_up)]
 96    prios.append(["Up", len(boost_up), _mean(diffs_up), _stdev(diffs_up)])
 97
 98    boost_down = [op for op in ops if op.operation == "\\_"]
 99    diffs_down = [n.uptime - p.uptime for p,n in itertools.pairwise(boost_down)]
100    prios.append(["Down", len(boost_down), _mean(diffs_down), _stdev(diffs_down)])
101
102    boost_255 = [op for op in ops if op.operation == "_/" and op.prio_to == 255]
103    diffs_255 = [n.uptime - p.uptime for p,n in itertools.pairwise(boost_255)]
104    prios.append(["255", len(boost_255), _mean(diffs_255), _stdev(diffs_255)])
105
106    fmtstr = "{:%d}  {:>%d} ~{:>%d}ms ±{:>%d}ms"
107    header = ["KIND", "#BOOSTS", "MEAN", "STDEV"]
108    output.append("")
109    output.append(format_table(fmtstr, header, prios))
110
111    # Print summary statistics per task
112    fmtstr = "{:%d}  {:>%d} {:>%d}%%  [{:>%d}, {:>%d}]   {:%d}   {:>%d}  {:%d}"
113    header = ["TASK", "#BOOSTS", "PCT", "MIN", "MAX", "REASONS", "#MAX", "REASONS FOR MAX"]
114    tasks = defaultdict(list)
115    for op in ops:
116        tasks[op.task].append(op)
117    task_prios = [[
118            task,
119            boosts := sum(1 for o in ops if o if o.operation == "_/"),
120            f"{boosts * 100 / len(boost_up):.1f}",
121            min(o.prio_from for o in ops),
122            max_prio := max(o.prio_to for o in ops),
123            ", ".join(sorted({o.reason for o in ops if o.reason is not None})),
124            sum(1 for o in ops if o if o.operation == "_/" and o.prio_to == max_prio),
125            ", ".join(sorted({o.reason for o in ops if o.reason is not None and o.prio_to == max_prio}))
126        ]
127        for task, ops in tasks.items()]
128    task_prios.sort(key=lambda t: (t[4], t[3], t[0], t[1]))
129    output.append("")
130    output.append(format_table(fmtstr, header, task_prios))
131
132    semtasks = defaultdict(list)
133    semtasksr = defaultdict(list)
134    for op in ops:
135        if op.semaphore is not None:
136            semtasks[op.semaphore].append(op.task)
137            if op.reason: semtasksr[op.semaphore].append(op.reason)
138    semtasks = [[hex(s), len(ts), ", ".join(sorted(set(ts))), ", ".join(sorted(set(semtasksr.get(s, []))))] for s, ts in semtasks.items()]
139    semtasks.sort(key=lambda s: -s[1])
140    fmtstr = "{:%d}  {:>%d}  {:%d}  {:%d}"
141    header = ["SEMAPHORE", "#BOOSTS", "BOOSTS THESE TASKS", "BECAUSE OF THESE TASKS"]
142    output.append("")
143    output.append(format_table(fmtstr, header, semtasks))
144
145    return "\n".join(output)
146
147
148# -----------------------------------------------------------------------------
149if __name__ == "__main__":
150    import argparse
151
152    parser = argparse.ArgumentParser(description="Priority Ceiling Analyzer")
153    parser.add_argument(
154        "file",
155        type=Path,
156        help="The GDB log containing the semaphore boost trace.")
157    args = parser.parse_args()
158
159    print(summarize_semaphore_boostlog(args.file))