diff --git a/tools/latency/.gitignore b/tools/latency/.gitignore new file mode 100644 index 0000000000..43ae0e2a6c --- /dev/null +++ b/tools/latency/.gitignore @@ -0,0 +1,2 @@ +__pycache__/ +*.py[cod] diff --git a/tools/latency/README.md b/tools/latency/README.md new file mode 100644 index 0000000000..fce277ccdd --- /dev/null +++ b/tools/latency/README.md @@ -0,0 +1,82 @@ +# Controller latency analyzer + +This tool calculates BLE connection-event timing from controller traces. It is +intended to establish a repeatable baseline before changing the Link Layer +scheduler. The report includes event duration, connection-event interval, +schedule lateness, skipped event counters, malformed counter transitions, +unmatched trace events, and p50, p95, p99, and maximum values. + +## Input + +Export controller trace events to CSV with this header: + +```text +timestamp_us,event,conn_handle,event_counter,scheduled_us +``` + +`event` accepts the SystemView names `ll_conn_ev_start` and +`ll_conn_ev_end`, or the shorter names `start` and `end`. `event_counter` is +normally available on end events. `scheduled_us` is optional; include it on a +start event to measure scheduler lateness. + +Example: + +```text +timestamp_us,event,conn_handle,event_counter,scheduled_us +1000,ll_conn_ev_start,0x0001,,990 +1125,ll_conn_ev_end,0x0001,42, +8500,ll_conn_ev_start,0x0001,,8490 +8620,ll_conn_ev_end,0x0001,43, +``` + +Enable `BLE_LL_SYSVIEW` in the controller configuration to emit the existing +connection start and end trace events. + +NimBLE's `ll_sched` trace event also contains the current controller tick and +the scheduled start tick. The SystemView export adapter converts their +wrap-safe difference to microseconds and places the result in `scheduled_us` +as `timestamp_us - schedule_delay_us`. This avoids adding instrumentation in +the timing-sensitive controller callback. + +The included adapter performs that conversion from a normalized SystemView CSV +containing `timestamp_us` and `message` columns. Pass the controller timer +frequency explicitly; it depends on the target configuration. + +```sh +python3 tools/latency/systemview_to_csv.py \ + --timer-hz 32768 systemview.csv > trace.csv +``` + +The expected message text is the text emitted by the existing trace +descriptions, for example: + +```text +ll_sched lls=0 cputime=105 start_time=100 +ll_conn_ev_start conn_handle=1 +ll_conn_ev_end conn_handle=1 event_cntr=42 +``` + +## Usage + +```sh +python3 tools/latency/latency.py trace.csv > latency-report.json +``` + +Use `--fail-on-anomaly` in automated comparisons to return exit status 3 when +the trace contains unmatched events or duplicate/out-of-order counters. The +JSON report is still emitted for diagnosis. + +Run the self-contained tests with: + +```sh +python3 -m unittest discover -s tools/latency -p 'test_*.py' +``` + +For scheduler comparisons, collect identical workloads before and after a +change and compare p95/p99 schedule lateness and skipped event counters. A +counter gap can mean that the controller skipped an event or that the trace +lost a record, so interpret it together with the trace-integrity counters and +the reported schedule-lateness coverage. Average latency alone can hide the +scheduling failures this tool is designed to expose. +Check unmatched events and duplicate or out-of-order counters before trusting a +comparison; nonzero values can indicate an incomplete or reordered trace. diff --git a/tools/latency/latency.py b/tools/latency/latency.py new file mode 100644 index 0000000000..0ee539f72a --- /dev/null +++ b/tools/latency/latency.py @@ -0,0 +1,253 @@ +#!/usr/bin/env python3 +# Licensed to the Apache Software Foundation (ASF) under one or more +# contributor license agreements. See the NOTICE file distributed with +# this work for additional information regarding copyright ownership. +# The ASF licenses this file to you under the Apache License, Version 2.0. + +"""Analyze BLE controller connection-event latency from a CSV trace.""" + +import argparse +import csv +import json +import math +import sys +from collections import defaultdict + + +EVENT_ALIASES = { + "ll_conn_ev_start": "start", + "conn_start": "start", + "start": "start", + "ll_conn_ev_end": "end", + "conn_end": "end", + "end": "end", +} + +REQUIRED_COLUMNS = {"timestamp_us", "event", "conn_handle"} + + +def percentile(values, quantile): + """Return a linearly interpolated percentile.""" + if not values: + return None + ordered = sorted(values) + index = (len(ordered) - 1) * quantile + lower = math.floor(index) + upper = math.ceil(index) + if lower == upper: + return ordered[lower] + return (ordered[lower] * (upper - index) + + ordered[upper] * (index - lower)) + + +def distribution(values): + """Summarize a collection of microsecond measurements.""" + if not values: + return None + return { + "count": len(values), + "min_us": min(values), + "mean_us": sum(values) / len(values), + "p50_us": percentile(values, 0.50), + "p95_us": percentile(values, 0.95), + "p99_us": percentile(values, 0.99), + "max_us": max(values), + } + + +def missed_between(first, second): + """Count skipped 16-bit Bluetooth event counters, including wrap.""" + skipped, anomaly = counter_transition(first, second) + if anomaly: + raise ValueError("invalid event counter transition: %s" % anomaly) + return skipped + + +def counter_transition(first, second): + """Classify an event-counter transition without inflating missed counts.""" + delta = (second - first) & 0xffff + if delta == 0: + return 0, "duplicate" + if delta > 0x8000: + return 0, "out_of_order" + return delta - 1, None + + +def read_trace(stream): + """Read and normalize latency events from a CSV stream.""" + reader = csv.DictReader(stream) + columns = set(reader.fieldnames or ()) + missing = sorted(REQUIRED_COLUMNS - columns) + if missing: + raise ValueError("missing trace columns: %s" % ", ".join(missing)) + + rows = [] + for line_number, row in enumerate(reader, start=2): + try: + event = EVENT_ALIASES[row["event"].strip()] + normalized = { + "timestamp_us": float(row["timestamp_us"]), + "event": event, + "conn_handle": int(row["conn_handle"], 0), + "event_counter": None, + "scheduled_us": None, + } + if row.get("event_counter", "").strip(): + normalized["event_counter"] = int(row["event_counter"], 0) + if row.get("scheduled_us", "").strip(): + normalized["scheduled_us"] = float(row["scheduled_us"]) + if not math.isfinite(normalized["timestamp_us"]): + raise ValueError("timestamp_us must be finite") + if normalized["timestamp_us"] < 0: + raise ValueError("timestamp_us must not be negative") + if not 0 <= normalized["conn_handle"] <= 0x0eff: + raise ValueError("conn_handle must be between 0 and 0x0eff") + if (normalized["event_counter"] is not None and + not 0 <= normalized["event_counter"] <= 0xffff): + raise ValueError("event_counter must be between 0 and 0xffff") + if (normalized["scheduled_us"] is not None and + (not math.isfinite(normalized["scheduled_us"]) or + normalized["scheduled_us"] < 0)): + raise ValueError("scheduled_us must be finite and nonnegative") + rows.append(normalized) + except (KeyError, TypeError, ValueError) as error: + raise ValueError("invalid trace row %d: %s" % + (line_number, error)) from error + return sorted(rows, key=lambda row: row["timestamp_us"]) + + +def analyze(rows): + """Calculate per-connection and aggregate latency measurements.""" + connections = defaultdict(list) + for row in rows: + connections[row["conn_handle"]].append(row) + + reports = {} + all_intervals = [] + all_durations = [] + all_lateness = [] + total_missed = 0 + total_unmatched_starts = 0 + total_unmatched_ends = 0 + total_duplicate_counters = 0 + total_out_of_order_counters = 0 + total_starts = 0 + total_lateness_samples = 0 + + for handle, events in sorted(connections.items()): + starts = [event for event in events if event["event"] == "start"] + ends = [event for event in events if event["event"] == "end"] + intervals = [second["timestamp_us"] - first["timestamp_us"] + for first, second in zip(starts, starts[1:])] + lateness = [event["timestamp_us"] - event["scheduled_us"] + for event in starts if event["scheduled_us"] is not None] + lateness_coverage = len(lateness) / len(starts) if starts else None + + pending = None + unmatched_starts = 0 + unmatched_ends = 0 + durations = [] + for event in events: + if event["event"] == "start": + if pending is not None: + unmatched_starts += 1 + pending = event["timestamp_us"] + elif pending is None: + unmatched_ends += 1 + else: + durations.append(event["timestamp_us"] - pending) + pending = None + + if pending is not None: + unmatched_starts += 1 + + counters = [event["event_counter"] for event in ends + if event["event_counter"] is not None] + missed = 0 + duplicate_counters = 0 + out_of_order_counters = 0 + for first, second in zip(counters, counters[1:]): + skipped, anomaly = counter_transition(first, second) + missed += skipped + duplicate_counters += anomaly == "duplicate" + out_of_order_counters += anomaly == "out_of_order" + + reports[str(handle)] = { + "events_started": len(starts), + "events_ended": len(ends), + "unmatched_starts": unmatched_starts, + "unmatched_ends": unmatched_ends, + "skipped_event_counters": missed, + "duplicate_event_counters": duplicate_counters, + "out_of_order_event_counters": out_of_order_counters, + "schedule_lateness_sample_count": len(lateness), + "schedule_lateness_coverage": lateness_coverage, + "start_interval": distribution(intervals), + "event_duration": distribution(durations), + "schedule_lateness": distribution(lateness), + } + all_intervals.extend(intervals) + all_durations.extend(durations) + all_lateness.extend(lateness) + total_missed += missed + total_unmatched_starts += unmatched_starts + total_unmatched_ends += unmatched_ends + total_duplicate_counters += duplicate_counters + total_out_of_order_counters += out_of_order_counters + total_starts += len(starts) + total_lateness_samples += len(lateness) + + return { + "connections": reports, + "aggregate": { + "connection_count": len(reports), + "skipped_event_counters": total_missed, + "unmatched_starts": total_unmatched_starts, + "unmatched_ends": total_unmatched_ends, + "duplicate_event_counters": total_duplicate_counters, + "out_of_order_event_counters": total_out_of_order_counters, + "schedule_lateness_sample_count": total_lateness_samples, + "schedule_lateness_coverage": ( + total_lateness_samples / total_starts if total_starts else None), + "start_interval": distribution(all_intervals), + "event_duration": distribution(all_durations), + "schedule_lateness": distribution(all_lateness), + }, + } + + +def has_anomalies(report): + """Return whether trace-integrity counters indicate unreliable input.""" + aggregate = report["aggregate"] + return any(aggregate[key] for key in ( + "unmatched_starts", + "unmatched_ends", + "duplicate_event_counters", + "out_of_order_event_counters", + )) + + +def main(): + parser = argparse.ArgumentParser(description=__doc__) + parser.add_argument("trace", type=argparse.FileType("r"), + help="CSV trace to analyze") + parser.add_argument("--indent", type=int, default=2, + help="JSON indentation (default: 2)") + parser.add_argument("--fail-on-anomaly", action="store_true", + help="exit 3 when trace-integrity anomalies are found") + args = parser.parse_args() + + try: + report = analyze(read_trace(args.trace)) + except ValueError as error: + print(error, file=sys.stderr) + return 2 + json.dump(report, sys.stdout, indent=args.indent, sort_keys=True) + print() + if args.fail_on_anomaly and has_anomalies(report): + return 3 + return 0 + + +if __name__ == "__main__": + sys.exit(main()) diff --git a/tools/latency/systemview_to_csv.py b/tools/latency/systemview_to_csv.py new file mode 100644 index 0000000000..b2b8ea8224 --- /dev/null +++ b/tools/latency/systemview_to_csv.py @@ -0,0 +1,117 @@ +#!/usr/bin/env python3 +# Licensed to the Apache Software Foundation (ASF) under one or more +# contributor license agreements. See the NOTICE file distributed with +# this work for additional information regarding copyright ownership. +# The ASF licenses this file to you under the Apache License, Version 2.0. + +"""Convert normalized SystemView messages to latency-analyzer CSV.""" + +import argparse +import csv +import re +import sys + + +MESSAGE = re.compile(r"(?Pll_[a-z_]+)(?P.*)") +FIELD = re.compile(r"([a-z_]+)=(0x[0-9a-fA-F]+|[0-9]+)") + + +def parse_message(message): + """Return an event name and its integer key-value fields.""" + match = MESSAGE.search(message) + if not match: + return None, {} + fields = {key: int(value, 0) + for key, value in FIELD.findall(match.group("fields"))} + return match.group("event"), fields + + +def tick_delta(current, scheduled, counter_bits): + """Return the signed wrap-safe difference between controller ticks.""" + modulus = 1 << counter_bits + delta = (current - scheduled) & (modulus - 1) + if delta >= modulus // 2: + delta -= modulus + return delta + + +def convert(source, destination, timer_hz, counter_bits=32): + """Convert timestamp_us,message rows into analyzer input rows.""" + if timer_hz <= 0: + raise ValueError("timer frequency must be positive") + if not 1 <= counter_bits <= 64: + raise ValueError("counter width must be between 1 and 64 bits") + + reader = csv.DictReader(source) + required = {"timestamp_us", "message"} + missing = sorted(required - set(reader.fieldnames or ())) + if missing: + raise ValueError("missing SystemView columns: %s" % + ", ".join(missing)) + + writer = csv.DictWriter( + destination, + fieldnames=["timestamp_us", "event", "conn_handle", + "event_counter", "scheduled_us"]) + writer.writeheader() + pending_delay_us = None + + for line_number, row in enumerate(reader, start=2): + try: + timestamp_us = float(row["timestamp_us"]) + event, fields = parse_message(row["message"]) + if event == "ll_sched": + delay_ticks = tick_delta(fields["cputime"], + fields["start_time"], counter_bits) + pending_delay_us = delay_ticks * 1000000.0 / timer_hz + elif event == "ll_conn_ev_start": + scheduled_us = "" + if pending_delay_us is not None: + scheduled_us = timestamp_us - pending_delay_us + writer.writerow({ + "timestamp_us": timestamp_us, + "event": event, + "conn_handle": fields["conn_handle"], + "event_counter": "", + "scheduled_us": scheduled_us, + }) + pending_delay_us = None + elif event == "ll_conn_ev_end": + writer.writerow({ + "timestamp_us": timestamp_us, + "event": event, + "conn_handle": fields["conn_handle"], + "event_counter": fields["event_cntr"], + "scheduled_us": "", + }) + pending_delay_us = None + elif event is not None: + # A connection-start trace is emitted immediately by its + # scheduler callback. Any other LL event makes an unmatched + # scheduler sample unsafe to associate with a later start. + pending_delay_us = None + except (KeyError, TypeError, ValueError) as error: + raise ValueError("invalid SystemView row %d: %s" % + (line_number, error)) from error + + +def main(): + parser = argparse.ArgumentParser(description=__doc__) + parser.add_argument("trace", type=argparse.FileType("r"), + help="CSV with timestamp_us and message columns") + parser.add_argument("--timer-hz", type=float, required=True, + help="controller timer frequency in Hz") + parser.add_argument("--counter-bits", type=int, default=32, + help="controller timer width (default: 32)") + args = parser.parse_args() + + try: + convert(args.trace, sys.stdout, args.timer_hz, args.counter_bits) + except ValueError as error: + print(error, file=sys.stderr) + return 2 + return 0 + + +if __name__ == "__main__": + sys.exit(main()) diff --git a/tools/latency/test_latency.py b/tools/latency/test_latency.py new file mode 100644 index 0000000000..e60c2668f9 --- /dev/null +++ b/tools/latency/test_latency.py @@ -0,0 +1,129 @@ +#!/usr/bin/env python3 +# Licensed to the Apache Software Foundation (ASF) under one or more +# contributor license agreements. See the NOTICE file distributed with +# this work for additional information regarding copyright ownership. +# The ASF licenses this file to you under the Apache License, Version 2.0. + +import io +import unittest + +import latency + + +TRACE = """timestamp_us,event,conn_handle,event_counter,scheduled_us +100,start,0x0001,,90 +180,end,0x0001,10, +1100,start,0x0001,,1090 +1190,end,0x0001,11, +3100,start,0x0001,,3050 +3210,end,0x0001,13, +200,start,0x0002,, +260,end,0x0002,20, +""" + + +class LatencyTest(unittest.TestCase): + def test_analyze_connections(self): + report = latency.analyze(latency.read_trace(io.StringIO(TRACE))) + + self.assertEqual(report["aggregate"]["connection_count"], 2) + self.assertEqual(report["aggregate"]["skipped_event_counters"], 1) + self.assertEqual(report["connections"]["1"]["events_started"], 3) + self.assertEqual( + report["connections"]["1"]["start_interval"]["max_us"], 2000) + self.assertEqual( + report["connections"]["1"]["event_duration"]["p50_us"], 90) + self.assertEqual( + report["connections"]["1"]["schedule_lateness"]["max_us"], 50) + self.assertEqual( + report["connections"]["1"]["schedule_lateness_coverage"], 1) + + def test_rejects_unknown_event(self): + trace = io.StringIO( + "timestamp_us,event,conn_handle\n1,unknown,1\n") + with self.assertRaisesRegex(ValueError, "invalid trace row 2"): + latency.read_trace(trace) + + def test_empty_trace(self): + trace = io.StringIO( + "timestamp_us,event,conn_handle,event_counter,scheduled_us\n") + report = latency.analyze(latency.read_trace(trace)) + self.assertEqual(report["aggregate"]["connection_count"], 0) + self.assertIsNone(report["aggregate"]["event_duration"]) + + def test_event_counter_wrap(self): + self.assertEqual(latency.missed_between(0xffff, 0), 0) + self.assertEqual(latency.missed_between(0xfffe, 1), 2) + + def test_dropped_end_does_not_corrupt_next_duration(self): + trace = io.StringIO( + "timestamp_us,event,conn_handle,event_counter\n" + "100,start,1,\n" + "200,start,1,\n" + "275,end,1,10\n") + report = latency.analyze(latency.read_trace(trace))["connections"]["1"] + + self.assertEqual(report["unmatched_starts"], 1) + self.assertEqual(report["unmatched_ends"], 0) + self.assertEqual(report["event_duration"]["max_us"], 75) + + def test_counter_anomalies_are_not_reported_as_missed_events(self): + trace = io.StringIO( + "timestamp_us,event,conn_handle,event_counter\n" + "100,end,1,10\n" + "200,end,1,10\n" + "300,end,1,9\n") + report = latency.analyze(latency.read_trace(trace))["connections"]["1"] + + self.assertEqual(report["skipped_event_counters"], 0) + self.assertEqual(report["duplicate_event_counters"], 1) + self.assertEqual(report["out_of_order_event_counters"], 1) + self.assertEqual(report["unmatched_ends"], 3) + + def test_rejects_missing_columns(self): + with self.assertRaisesRegex(ValueError, "missing trace columns"): + latency.read_trace(io.StringIO("timestamp_us,event\n1,start\n")) + + def test_rejects_nonfinite_and_out_of_range_values(self): + invalid_rows = ( + "nan,start,1,,", + "-1,start,1,,", + "1,start,0x0f00,,", + "1,end,1,65536,", + "1,start,1,,inf", + ) + header = "timestamp_us,event,conn_handle,event_counter,scheduled_us\n" + for row in invalid_rows: + with self.subTest(row=row): + with self.assertRaisesRegex(ValueError, "invalid trace row 2"): + latency.read_trace(io.StringIO(header + row + "\n")) + + def test_reports_partial_lateness_coverage(self): + trace = io.StringIO( + "timestamp_us,event,conn_handle,scheduled_us\n" + "100,start,1,90\n" + "200,end,1,\n" + "300,start,1,\n") + report = latency.analyze(latency.read_trace(trace))["connections"]["1"] + + self.assertEqual(report["schedule_lateness_sample_count"], 1) + self.assertEqual(report["schedule_lateness_coverage"], 0.5) + self.assertTrue(latency.has_anomalies({"aggregate": report})) + + +class CounterTransitionTest(unittest.TestCase): + def test_duplicate(self): + self.assertEqual(latency.counter_transition(10, 10), + (0, "duplicate")) + + def test_out_of_order(self): + self.assertEqual(latency.counter_transition(10, 9), + (0, "out_of_order")) + + def test_missed_between_rejects_anomalies(self): + with self.assertRaisesRegex(ValueError, "duplicate"): + latency.missed_between(10, 10) + + +if __name__ == "__main__": + unittest.main() diff --git a/tools/latency/test_systemview_to_csv.py b/tools/latency/test_systemview_to_csv.py new file mode 100644 index 0000000000..c5b9a811c8 --- /dev/null +++ b/tools/latency/test_systemview_to_csv.py @@ -0,0 +1,68 @@ +#!/usr/bin/env python3 +# Licensed to the Apache Software Foundation (ASF) under one or more +# contributor license agreements. See the NOTICE file distributed with +# this work for additional information regarding copyright ownership. +# The ASF licenses this file to you under the Apache License, Version 2.0. + +import csv +import io +import unittest +from pathlib import Path + +import systemview_to_csv + + +TRACE = """timestamp_us,message +1000,ll_sched lls=0 cputime=105 start_time=100 +1010,ll_conn_ev_start conn_handle=1 +1090,ll_conn_ev_end conn_handle=1 event_cntr=42 +""" + + +class SystemViewToCsvTest(unittest.TestCase): + def test_normalized_systemview_fixture(self): + testdata = Path(__file__).with_name("testdata") + output = io.StringIO() + with (testdata / "normalized_systemview.csv").open() as source: + systemview_to_csv.convert(source, output, timer_hz=1000000) + with (testdata / "expected_trace.csv").open() as expected: + self.assertEqual(list(csv.DictReader(io.StringIO(output.getvalue()))), + list(csv.DictReader(expected))) + + def test_converts_connection_events_and_scheduler_lateness(self): + output = io.StringIO() + systemview_to_csv.convert(io.StringIO(TRACE), output, timer_hz=1000000) + rows = list(csv.DictReader(io.StringIO(output.getvalue()))) + + self.assertEqual(len(rows), 2) + self.assertEqual(rows[0]["event"], "ll_conn_ev_start") + self.assertEqual(float(rows[0]["scheduled_us"]), 1005) + self.assertEqual(rows[1]["event_counter"], "42") + + def test_tick_delta_handles_wrap(self): + self.assertEqual(systemview_to_csv.tick_delta(1, 0xffffffff, 32), 2) + + def test_rejects_missing_columns(self): + with self.assertRaisesRegex(ValueError, "missing SystemView columns"): + systemview_to_csv.convert( + io.StringIO("timestamp_us\n1\n"), io.StringIO(), 1000000) + + def test_does_not_reuse_scheduler_sample_after_another_event(self): + trace = io.StringIO( + "timestamp_us,message\n" + "1000,ll_sched lls=0 cputime=105 start_time=100\n" + "1005,ll_adv_txdone inst=0 chanset=7\n" + "1010,ll_conn_ev_start conn_handle=1\n") + output = io.StringIO() + systemview_to_csv.convert(trace, output, timer_hz=1000000) + rows = list(csv.DictReader(io.StringIO(output.getvalue()))) + + self.assertEqual(rows[0]["scheduled_us"], "") + + def test_rejects_invalid_timer_configuration(self): + with self.assertRaisesRegex(ValueError, "frequency must be positive"): + systemview_to_csv.convert(io.StringIO(TRACE), io.StringIO(), 0) + + +if __name__ == "__main__": + unittest.main() diff --git a/tools/latency/testdata/expected_trace.csv b/tools/latency/testdata/expected_trace.csv new file mode 100644 index 0000000000..dff384ee99 --- /dev/null +++ b/tools/latency/testdata/expected_trace.csv @@ -0,0 +1,5 @@ +timestamp_us,event,conn_handle,event_counter,scheduled_us +1010.0,ll_conn_ev_start,1,,1005.0 +1090.0,ll_conn_ev_end,1,42, +2000.0,ll_conn_ev_start,2,, +2075.0,ll_conn_ev_end,2,7, diff --git a/tools/latency/testdata/normalized_systemview.csv b/tools/latency/testdata/normalized_systemview.csv new file mode 100644 index 0000000000..3f3f7b3764 --- /dev/null +++ b/tools/latency/testdata/normalized_systemview.csv @@ -0,0 +1,6 @@ +timestamp_us,message +1000,ll_sched lls=0 cputime=105 start_time=100 +1010,ll_conn_ev_start conn_handle=1 +1090,ll_conn_ev_end conn_handle=1 event_cntr=42 +2000,ll_conn_ev_start conn_handle=2 +2075,ll_conn_ev_end conn_handle=2 event_cntr=7