#!/usr/bin/env python3 """ Generate a driver/library benchmark based on DFA/PTA traces. Usage: bin/generate-dfa-benchmark.py [options] [output.cc] generate-dfa-benchmarks reads in a DFA definition and generates runs (i.e., all words accepted by the DFA up to a configurable length). Each symbol corresponds to a function call. If arguments are specified in the DFA definition, each symbol corresponds to a function call with a specific set of arguments (so all argument combinations are present in the generated runs). It expects to be called from a multipass instance and writes data to ../data. Recommended setup: > mkdir -p data/cache > git clone .../dfatool > git clone .../multipass > cd multipass > ../dfatool/bin/generate-dfa-benchmark.py ... src/app/aemr/main.cc Options: --accounting=static_state|static_state_immediate|static_statetransition|static_statetransition_immedate[,opt1=val1,opt2=val2,...] Select accounting method for dummy driver generation. May be followed by a list of key=value driver options, e.g. energy_type=uint64_t --data= Directory in which the measurements will be stored. Default: ../data --dummy= Generate and use a dummy driver for online energy model overhead evaluation --depth= (default: 3) Maximum number of function calls per run --repeat= (default: 0) Repeat benchmark runs times. When 0, benchmark runs are repeated indefinitely and must be explicitly terminated with Ctrl+C / SIGINT --instance= Override the name of the class instance used for benchmarking --mimosa=[k=v,k=v,...] Perform energy measurements with MIMOSA. Takes precedence over --timing and --energytrace. mimosa options are key-value pairs. Possible settings with defaults: offset = 130 (mysterious 0V offset) shunt = 330 (measurement shunt in ohms) voltage = 3.3 (VCC provided to DUT) --os=kratos|multipass (default: multipass) --sleep= (default: 0) How long to sleep between function calls. --shrink Decrease amount of parameter values used in state space exploration (only use minimum and maximum for numeric values) --timing Perform timing measurements using on-chip counters (no external hardware required) --energytrace=[k=v,k=v,...] Perform energy measurements using MSP430 EnergyTrace hardware. Includes --timing. Additional configuration settings: sync = bar (Barcode mode (default): synchronize measurements via barcodes embedded in the energy trace) sync = la (Logic Analyzer mode (WIP): An external logic analyzer captures transition timing) sync = timing (Timing mode (WIP): The on-board cycle counter captures transition timing) plusplus = 0 (default, EnergyTrace measurements with about 3.7 kHz sample rate, energy only) plusplus = 1 (EnergyTrace++ measurements with about 1 kHz sample rate, energy and cpu state) --external= Perform energy measurements using an external device unknown to dfatool. With --external=gpio: Assume the device has a trigger input connected to timer-pin and toggle it when starting/topping a transition With --external=timer: Assume the device does not have a trigger input. Perform in-band signaling using board LEDs instead. --trace-filter=[ ...] Only consider traces whose beginning matches one of the provided transition sequences. E.g. --trace-filter='init,foo init,bar' will only consider traces with init as first and foo or bar as second transition, and --trace-filter='init,foo,$ init,bar,$' will only consider the traces init -> foo and init -> bar. EXAMPLES Perform timing measurements of nRF24L01+ function calls: ../dfatool/bin/generate-dfa-benchmark.py --timer-pin=GPIO::p1_0 --sleep=200 --repeat=3 --depth=10 --arch=msp430fr5994lp --timing --trace-filter='setup,setAutoAck,setDataRate,setPALevel,write,$' model/driver/nrf24l01.dfa src/app/aemr/main.cc Perform timing measurements of BME680 funtion calls: ../dfatool/bin/generate-dfa-benchmark.py --timer-pin=GPIO::p1_0 --sleep=200 --repeat=3 --depth=10 --arch=msp430fr5994lp --timing --trace-filter='init,configure,setSensorSettings,setPowerMode,setSensorMode,getSensorData,$' --shrink model/driver/bme680.dfa src/app/aemr/main.cc """ import getopt import json import logging import os import re import sys import tarfile import time import io import yaml from dfatool import runner from dfatool.aspectc import Repo from dfatool.automata import PTA from dfatool.codegen import get_accountingmethod, MultipassDriver from dfatool.harness import OnboardTimerHarness, TransitionHarness from dfatool.utils import flatten opt = dict() def benchmark_from_runs( pta: PTA, runs: list, harness: OnboardTimerHarness, benchmark_id: int = 0, dummy=False, repeat=0, ) -> io.StringIO: outbuf = io.StringIO() outbuf.write(target.app_header()) if dummy: outbuf.write('#include "driver/dummy.h"\n') elif "includes" in pta.codegen: for include in pta.codegen["includes"]: outbuf.write('#include "{}"\n'.format(include)) outbuf.write(harness.global_code()) outbuf.write(target.app_function_start()) # There is a race condition between flashing the code and starting the UART log. # When starting the log before flashing, output from a previous benchmark may cause bogus data to be added. # When flashing first and then starting the log, the first log lines may be lost. # To work around this, we flash first, then start the log, and use this delay statement to ensure that no output is lost. # This is also useful to faciliate MIMOSA calibration after flashing # For MIMOSA, the DUT is disconnected from power during calibration, so # it must be set up after the calibration delay. # For energytrace, the device is connected to VCC and set up before # the initialization delay to -- this puts it into a well-defined state and # decreases pre-sync power consumption if "energytrace" not in opt: if "mimosa" in opt: outbuf.write(target.app_delay(12000)) else: outbuf.write(target.app_delay(2000)) # Output some newlines to ensure the parser can determine the start of the first real output line outbuf.write(target.app_newlines()) if "setup" in pta.codegen: for call in pta.codegen["setup"]: outbuf.write(call) if "energytrace" in opt: outbuf.write("for (unsigned char j = 0; j < 10; j++) {\n") outbuf.write(target.app_sleep(250)) outbuf.write("}\n") # Output some newlines to ensure the parser can determine the start of the first real output line outbuf.write(target.app_newlines()) if repeat: outbuf.write("unsigned char i = 0;\n") outbuf.write("while (i++ < {}) {{\n".format(repeat)) else: outbuf.write("while (1) {\n") outbuf.write(harness.start_benchmark()) class_prefix = "" if "instance" in opt: class_prefix = "{}.".format(opt["instance"]) elif "instance" in pta.codegen: class_prefix = "{}.".format(pta.codegen["instance"]) num_transitions = 0 num_traces = 0 for run in runs: outbuf.write(harness.start_run()) harness.start_trace() param = pta.get_initial_param_dict() for transition, arguments, parameter in run: num_transitions += 1 harness.append_transition(transition.name, param, arguments) harness.append_state(transition.destination.name, parameter.copy()) outbuf.write( "// {} -> {}\n".format( transition.origin.name, transition.destination.name ) ) if transition.is_interrupt: outbuf.write("// wait for {} interrupt\n".format(transition.name)) transition_code = "// TODO add startTransition / stopTransition calls to interrupt routine" else: transition_code = "{}{}({});".format( class_prefix, transition.name, ", ".join(map(str, arguments)) ) outbuf.write( harness.pass_transition( pta.get_transition_id(transition), transition_code, transition=transition, ) ) param = parameter outbuf.write( "// current parameters: {}\n".format( ", ".join(map(lambda kv: "{}={}".format(*kv), param.items())) ) ) if "delay_after_ms" in transition.codegen: if "energytrace" in opt: outbuf.write( target.app_sleep( transition.codegen["delay_after_ms"], f"{transition.destination.name} -- delay mandated by codegen.delay_after_ms", ) ) else: outbuf.write( target.app_delay( transition.codegen["delay_after_ms"], f"{transition.destination.name} -- delay mandated by codegen.delay_after_ms", ) ) elif opt["sleep"]: if "energytrace" in opt: outbuf.write(f"// -> {transition.destination.name}\n") outbuf.write(target.sleep_ms(opt["sleep"])) else: outbuf.write(f"// -> {transition.destination.name}\n") outbuf.write(target.app_delay(opt["sleep"])) outbuf.write(harness.stop_run(num_traces)) if dummy: outbuf.write( 'kout << "[Energy] " << {}getEnergy() << endl;\n'.format(class_prefix) ) outbuf.write("\n") num_traces += 1 outbuf.write(harness.stop_benchmark()) outbuf.write("}\n") # Ensure logging can be terminated after the specified number of measurements outbuf.write(harness.start_benchmark()) outbuf.write(target.app_function_end()) return outbuf def run_benchmark( application_file: str, pta: PTA, runs: list, arch: str, app: str, run_args: list, harness: object, sleep: int = 0, repeat: int = 0, run_offset: int = 0, runs_total: int = 0, dummy=False, ): if "mimosa" in opt or "energytrace" in opt: outbuf = benchmark_from_runs(pta, runs, harness, dummy=dummy, repeat=1) else: outbuf = benchmark_from_runs(pta, runs, harness, dummy=dummy, repeat=repeat) with open(application_file, "w") as f: f.write(outbuf.getvalue()) print("[MAKE] building benchmark with {:d} runs".format(len(runs))) # assume an average of 10ms per transition. Mind the 10s start delay. run_timeout = 10 + num_transitions * (sleep + 10) / 1000 if repeat: run_timeout *= repeat needs_split = False if len(runs) > 1000: needs_split = True else: try: target.build(app, run_args) except RuntimeError: if len(runs) > 50: # Application is too large -> split up runs needs_split = True else: # Unknown error raise # This has been deliberately taken out of the except clause to avoid nested exception handlers # (they lead to pretty interesting tracebacks which are probably more confusing than helpful) if needs_split: print("[MAKE] benchmark code is too large, splitting up") mid = len(runs) // 2 # Previously prepared trace data is useless harness.reset() results = run_benchmark( application_file, pta, runs[:mid], arch, app, run_args, harness.copy(), sleep, repeat, run_offset=run_offset, runs_total=runs_total, dummy=dummy, ) results.extend( run_benchmark( application_file, pta, runs[mid:], arch, app, run_args, harness.copy(), sleep, repeat, run_offset=run_offset + mid, runs_total=runs_total, dummy=dummy, ) ) return results if "mimosa" in opt or "energytrace" in opt: files = list() i = 0 while i < opt["repeat"]: print(f"""[RUN] flashing benchmark {i+1}/{opt["repeat"]}""") target.flash(app, run_args) if "mimosa" in opt: monitor = target.get_monitor( callback=harness.parser_cb, mimosa=opt["mimosa"] ) elif "energytrace" in opt: monitor = target.get_monitor( callback=harness.parser_cb, energytrace=opt["energytrace"] ) else: monitor = target.get_monitor(callback=harness.parser_cb) sync_error = False try: slept = 0 while not harness.done: # possible race condition: if the benchmark completes at this # exact point, it sets harness.done and unsets harness.synced. if ( slept > 30 and slept < 40 and not harness.synced and not harness.done ): print( "[RUN] has been unsynced for more than 30 seconds, assuming error. Retrying." ) sync_error = True break if harness.abort: print("[RUN] harness encountered an error. Retrying") sync_error = True break time.sleep(5) slept += 5 print( "[RUN] {:d}/{:d} ({:.0f}%) at trace {:d}".format( run_offset, runs_total, run_offset * 100 / runs_total, harness.trace_id, ) ) except KeyboardInterrupt: pass monitor.close() if sync_error: for filename in monitor.get_files(): os.remove(filename) harness.undo(i) else: files.append(monitor.get_files()) i += 1 harness.restart() return [(runs, harness, monitor, files)] else: target.flash(app, run_args) monitor = target.get_monitor(callback=harness.parser_cb) if arch == "posix": print("[RUN] Will run benchmark for {:.0f} seconds".format(run_timeout)) lines = monitor.run(int(run_timeout)) return [(runs, harness, lines, list())] try: slept = 0 while not harness.done: time.sleep(5) slept += 5 print( "[RUN] {:d}/{:d} ({:.0f}%), current benchmark at {:.0f}%".format( run_offset, runs_total, run_offset * 100 / runs_total, slept * 100 / run_timeout, ) ) except KeyboardInterrupt: pass monitor.close() return [(runs, harness, monitor, list())] if __name__ == "__main__": try: optspec = ( "accounting= " "arch= " "arch-flags= " "app= " "data= " "depth= " "dummy= " "energytrace= " "external= " "instance= " "log-level= " "mimosa= " "os= " "repeat= " "run= " "sleep= " "shrink " "timing " "timer-pin= " "trace-filter= " ) raw_opts, args = getopt.getopt(sys.argv[1:], "", optspec.split(" ")) for option, parameter in raw_opts: optname = re.sub(r"^--", "", option) opt[optname] = parameter if "app" not in opt: opt["app"] = "aemr" if "arch-flags" in opt: opt["arch-flags"] = opt["arch-flags"].split(",") else: opt["arch-flags"] = list() if "depth" in opt: opt["depth"] = int(opt["depth"]) else: opt["depth"] = 3 if "repeat" in opt: opt["repeat"] = int(opt["repeat"]) else: opt["repeat"] = 0 if "sleep" in opt: opt["sleep"] = int(opt["sleep"]) else: opt["sleep"] = 0 if "trace-filter" in opt: trace_filter = list() for trace in opt["trace-filter"].split(): trace_filter.append(trace.split(",")) opt["trace-filter"] = trace_filter else: opt["trace-filter"] = None if "log-level" in opt: numeric_level = getattr(logging, opt["log-level"].upper(), None) if not isinstance(numeric_level, int): print(f"Invalid log level: {args.log_level}", file=sys.stderr) sys.exit(1) logging.basicConfig(level=numeric_level) if "mimosa" in opt: if opt["mimosa"] == "": opt["mimosa"] = dict() else: opt["mimosa"] = dict( map(lambda x: x.split("="), opt["mimosa"].split(",")) ) opt.pop("timing", None) if opt["repeat"] == 0: opt["repeat"] = 1 if "energytrace" in opt: if opt["energytrace"] == "": opt["energytrace"] = dict() else: opt["energytrace"] = dict( map(lambda x: x.split("="), opt["energytrace"].split(",")) ) opt.pop("timing", None) if opt["repeat"] == 0: opt["repeat"] = 1 if "external" not in opt: opt["external"] = None if "data" not in opt: opt["data"] = "../data" if "dummy" in opt: if opt["dummy"] == "": opt["dummy"] = dict() else: opt["dummy"] = dict( map(lambda x: x.split("="), opt["dummy"].split(",")) ) if "os" not in opt: opt["os"] = "multipass" except getopt.GetoptError as err: print(err) sys.exit(2) if opt["os"] == "kratos": target = runner.KRATOS() elif "msp430fr" in opt["arch"]: if len(opt["arch-flags"]) == 0: opt["arch-flags"] = ["cpu_freq=8000000", "uart_freq=9600"] target = runner.Multipass(opt["arch"], opt["arch-flags"]) else: target = runner.Multipass(opt["arch"]) modelfile = args[0] pta = PTA.from_file(modelfile) run_flags = list() if "shrink" in opt: pta.shrink_argument_values() if "timer-pin" in opt: timer_pin = opt["timer-pin"] else: timer_pin = None if "dummy" in opt: enum = dict() if ".json" not in modelfile: with open(modelfile, "r") as f: driver_definition = yaml.safe_load(f) if ( "dummygen" in driver_definition and "enum" in driver_definition["dummygen"] ): enum = driver_definition["dummygen"]["enum"] if "class" in opt["dummy"]: class_name = opt["dummy"]["class"] else: class_name = driver_definition["codegen"]["class"] run_flags = ["drivers=dummy"] repo = Repo("../multipass/build/repo.acp") if "accounting" in opt and "getEnergy" not in map( lambda x: x.name, pta.transitions ): for state in pta.get_state_names(): pta.add_transition(state, state, "getEnergy") pta.set_random_energy_model() if "accounting" in opt: if "," in opt["accounting"]: accounting_settings = opt["accounting"].split(",") accounting_name = accounting_settings[0] accounting_options = dict( map(lambda x: x.split("="), accounting_settings[1:]) ) accounting_object = get_accountingmethod(accounting_name)( class_name, pta, **accounting_options ) else: accounting_object = get_accountingmethod(opt["accounting"])( class_name, pta ) else: accounting_object = None drv = MultipassDriver( class_name, pta, repo.class_by_name[class_name], enum=enum, accounting=accounting_object, ) with open("../multipass/src/driver/dummy.cc", "w") as f: f.write(drv.impl) with open("../multipass/include/driver/dummy.h", "w") as f: f.write(drv.header) if ".json" not in modelfile: with open(modelfile, "r") as f: driver_definition = yaml.safe_load(f) if "codegen" in driver_definition and "flags" in driver_definition["codegen"]: if not run_flags: run_flags = driver_definition["codegen"]["flags"] if "run" in opt: run_flags.extend(opt["run"].split()) runs = list( pta.dfs( opt["depth"], with_arguments=True, with_parameters=True, trace_filter=opt["trace-filter"], ) ) num_transitions = len(runs) if len(runs) == 0: print( "DFS returned no traces -- perhaps your trace-filter is too restrictive?", file=sys.stderr, ) sys.exit(1) need_return_values = False if next(filter(lambda x: len(x.return_value_handlers), pta.transitions), None): # A PTA transition indicates that its return value determines an online # parameter (e.g. Nrf24l01 getObserveTx, which is used to determine the # actual number of transmission retries after a write operation) need_return_values = True # elif 'accounting' in opt: # # getEnergy() returns energy data. Log it. # need_return_values = True if "mimosa" in opt: harness = TransitionHarness( gpio_pin=timer_pin, pta=pta, log_return_values=need_return_values, repeat=1, post_transition_delay_us=20, ) elif "energytrace" in opt: # Use barcode sync by default gpio_mode = "bar" energytrace_sync = None if "sync" in opt["energytrace"] and opt["energytrace"]["sync"] != "bar": gpio_mode = "around" energytrace_sync = "led" harness = OnboardTimerHarness( gpio_pin=timer_pin, gpio_mode=gpio_mode, pta=pta, counter_limits=target.get_counter_limits_us(run_flags), log_return_values=need_return_values, repeat=1, energytrace_sync=energytrace_sync, remove_nop_from_timings=False, # kein einfluss auf ungenauigkeiten ) elif "timing" in opt: harness = OnboardTimerHarness( gpio_pin=timer_pin, pta=pta, counter_limits=target.get_counter_limits_us(run_flags), log_return_values=need_return_values, repeat=opt["repeat"], ) elif opt["external"] == "gpio": harness = TransitionHarness( gpio_pin=timer_pin, pta=pta, log_return_values=need_return_values, repeat=1 ) elif opt["external"] == "timer": harness = OnboardTimerHarness( gpio_pin=timer_pin, gpio_mode="around", pta=pta, counter_limits=target.get_counter_limits_us(run_flags), log_return_values=need_return_values, repeat=1, energytrace_sync="led", remove_nop_from_timings=False, # kein einfluss auf ungenauigkeiten ) harness.target = target if len(args) > 1: results = run_benchmark( args[1], pta, runs, opt["arch"], opt["app"], run_flags, harness, opt["sleep"], opt["repeat"], runs_total=len(runs), dummy="dummy" in opt, ) json_out = { "opt": opt, "pta": pta.to_json(), "traces": list(map(lambda x: x[1].traces, results)), "raw_output": list(map(lambda x: x[2].get_lines(), results)), "files": list(map(lambda x: x[3], results)), "configs": list(map(lambda x: x[2].get_config(), results)), } extra_files = flatten(map(flatten, json_out["files"])) if "instance" in pta.codegen: output_prefix = ( opt["data"] + time.strftime("/%Y%m%d-%H%M%S-") + pta.codegen["instance"] ) else: output_prefix = opt["data"] + time.strftime("/%Y%m%d-%H%M%S-ptalog") if len(extra_files): with open("ptalog.json", "w") as f: json.dump(json_out, f) with tarfile.open("{}.tar".format(output_prefix), "w") as tar: tar.add("ptalog.json") for extra_file in extra_files: tar.add(extra_file) print(" --> {}.tar".format(output_prefix)) os.remove("ptalog.json") for extra_file in extra_files: os.remove(extra_file) else: with open("{}.json".format(output_prefix), "w") as f: json.dump(json_out, f) print(" --> {}.json".format(output_prefix)) else: outbuf = benchmark_from_runs(pta, runs, harness, repeat=opt["repeat"]) print(outbuf.getvalue()) sys.exit(0)