From 6ce21ce0e8f25c8fc9b4da6510f242cae17e3f71 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Jakub=20Urba=C5=84czyk?= Date: Thu, 14 Mar 2024 11:28:03 +0000 Subject: [PATCH] Hardware Logging (https://github.com/kuznia-rdzeni/coreblocks/pull/595) --- test/testing/test_assertion.py | 32 ---- test/testing/test_log.py | 124 ++++++++++++++ transactron/lib/logging.py | 229 ++++++++++++++++++++++++++ transactron/testing/__init__.py | 2 +- transactron/testing/assertion.py | 20 --- transactron/testing/infrastructure.py | 9 +- transactron/testing/logging.py | 108 ++++++++++++ transactron/utils/__init__.py | 1 - transactron/utils/assertion.py | 60 ------- transactron/utils/gen.py | 71 ++++---- 10 files changed, 510 insertions(+), 146 deletions(-) delete mode 100644 test/testing/test_assertion.py create mode 100644 test/testing/test_log.py create mode 100644 transactron/lib/logging.py delete mode 100644 transactron/testing/assertion.py create mode 100644 transactron/testing/logging.py delete mode 100644 transactron/utils/assertion.py diff --git a/test/testing/test_assertion.py b/test/testing/test_assertion.py deleted file mode 100644 index 4becf30..0000000 --- a/test/testing/test_assertion.py +++ /dev/null @@ -1,32 +0,0 @@ -from amaranth import * - -from transactron.utils import assertion -from transactron.testing import TestCaseWithSimulator - - -class AssertionTest(Elaboratable): - def __init__(self): - self.input = Signal() - self.output = Signal() - - def elaborate(self, platform): - m = Module() - - m.d.comb += self.output.eq(self.input & ~self.input) - - assertion(m, self.input == self.output) - - return m - - -class TestAssertion(TestCaseWithSimulator): - def test_assertion(self): - m = AssertionTest() - - def proc(): - yield - yield m.input.eq(1) - - with self.assertRaises(AssertionError): - with self.run_simulation(m) as sim: - sim.add_sync_process(proc) diff --git a/test/testing/test_log.py b/test/testing/test_log.py new file mode 100644 index 0000000..69f537f --- /dev/null +++ b/test/testing/test_log.py @@ -0,0 +1,124 @@ +from amaranth import * + +from transactron import * +from transactron.testing import TestCaseWithSimulator +from transactron.lib import logging + +LOGGER_NAME = "test_logger" + +log = logging.HardwareLogger(LOGGER_NAME) + + +class LogTest(Elaboratable): + def __init__(self): + self.input = Signal(range(100)) + self.counter = Signal(range(200)) + + def elaborate(self, platform): + m = TModule() + + with m.If(self.input == 42): + log.warning(m, True, "Log triggered under Amaranth If value+3=0x{:x}", self.input + 3) + + log.warning(m, self.input[0] == 0, "Input is even! input={}, counter={}", self.input, self.counter) + + m.d.sync += self.counter.eq(self.counter + 1) + + return m + + +class ErrorLogTest(Elaboratable): + def __init__(self): + self.input = Signal() + self.output = Signal() + + def elaborate(self, platform): + m = TModule() + + m.d.comb += self.output.eq(self.input & ~self.input) + + log.error( + m, + self.input != self.output, + "Input is different than output! input=0x{:x} output=0x{:x}", + self.input, + self.output, + ) + + return m + + +class AssertionTest(Elaboratable): + def __init__(self): + self.input = Signal() + self.output = Signal() + + def elaborate(self, platform): + m = TModule() + + m.d.comb += self.output.eq(self.input & ~self.input) + + log.assertion(m, self.input == self.output, "Output differs") + + return m + + +class TestLog(TestCaseWithSimulator): + def test_log(self): + m = LogTest() + + def proc(): + for i in range(50): + yield + yield m.input.eq(i) + + with self.assertLogs(LOGGER_NAME) as logs: + with self.run_simulation(m) as sim: + sim.add_sync_process(proc) + + self.assertIn( + "WARNING:test_logger:test/transactron/testing/test_log.py:21] Log triggered under Amaranth If value+3=0x2d", + logs.output, + ) + for i in range(0, 50, 2): + expected_msg = ( + "WARNING:test_logger:test/transactron/testing/test_log.py:23] " + + f"Input is even! input={i}, counter={i + 2}" + ) + self.assertIn( + expected_msg, + logs.output, + ) + + def test_error_log(self): + m = ErrorLogTest() + + def proc(): + yield + yield m.input.eq(1) + + with self.assertLogs(LOGGER_NAME) as logs: + with self.assertRaises(AssertionError): + with self.run_simulation(m) as sim: + sim.add_sync_process(proc) + + extected_out = ( + "ERROR:test_logger:test/transactron/testing/test_log.py:40] " + + "Input is different than output! input=0x1 output=0x0" + ) + self.assertIn(extected_out, logs.output) + + def test_assertion(self): + m = AssertionTest() + + def proc(): + yield + yield m.input.eq(1) + + with self.assertLogs(LOGGER_NAME) as logs: + with self.assertRaises(AssertionError): + with self.run_simulation(m) as sim: + sim.add_sync_process(proc) + + extected_out = "ERROR:test_logger:test/transactron/testing/test_log.py:61] Output differs" + self.assertIn(extected_out, logs.output) diff --git a/transactron/lib/logging.py b/transactron/lib/logging.py new file mode 100644 index 0000000..7eb06de --- /dev/null +++ b/transactron/lib/logging.py @@ -0,0 +1,229 @@ +import os +import re +import operator +import logging +from functools import reduce +from dataclasses import dataclass, field +from dataclasses_json import dataclass_json +from typing import TypeAlias + +from amaranth import * +from amaranth.tracer import get_src_loc + +from transactron.utils import SrcLoc +from transactron.utils._typing import ModuleLike, ValueLike +from transactron.utils.dependencies import DependencyContext, ListKey + +LogLevel: TypeAlias = int + + +@dataclass_json +@dataclass +class LogRecordInfo: + """Simulator-backend-agnostic information about a log record that can + be serialized and used outside the Amaranth context. + + Attributes + ---------- + logger_name: str + + level: LogLevel + The severity level of the log. + format_str: str + The template of the message. Should follow PEP 3101 standard. + location: SrcLoc + Source location of the log. + """ + + logger_name: str + level: LogLevel + format_str: str + location: SrcLoc + + def format(self, *args) -> str: + """Format the log message with a set of concrete arguments.""" + + return self.format_str.format(*args) + + +@dataclass +class LogRecord(LogRecordInfo): + """A LogRecord instance represents an event being logged. + + Attributes + ---------- + trigger: Signal + Amaranth signal triggering the log. + fields: Signal + Amaranth signals that will be used to format the message. + """ + + trigger: Signal + fields: list[Signal] = field(default_factory=list) + + +@dataclass(frozen=True) +class LogKey(ListKey[LogRecord]): + pass + + +class HardwareLogger: + """A class for creating log messages in the hardware. + + Intuitively, the hardware logger works similarly to a normal software + logger. You can log a message anywhere in the circuit, but due to the + parallel nature of the hardware you must specify a special trigger signal + which will indicate if a message shall be reported in that cycle. + + Hardware logs are evaluated and printed during simulation, so both + the trigger and the format fields are Amaranth values, i.e. + signals or arbitrary Amaranth expressions. + + Instances of the HardwareLogger class represent a logger for a single + submodule of the circuit. Exactly how a "submodule" is defined is up + to the developer. Submodule are identified by a unique string and + the names can be nested. Names are organized into a namespace hierarchy + where levels are separated by periods, much like the Python package + namespace. So in the instance, submodules names might be "frontend" + for the upper level, and "frontend.icache" and "frontend.bpu" for + the sub-levels. There is no arbitrary limit to the depth of nesting. + + Attributes + ---------- + name: str + Name of this logger. + """ + + def __init__(self, name: str): + """ + Parameters + ---------- + name: str + Name of this logger. Hierarchy levels are separated by periods, + e.g. "backend.fu.jumpbranch". + """ + self.name = name + + def log(self, m: ModuleLike, level: LogLevel, trigger: ValueLike, format: str, *args, src_loc_at: int = 0): + """Registers a hardware log record with the given severity. + + Parameters + ---------- + m: ModuleLike + The module for which the log record is added. + trigger: ValueLike + If the value of this Amaranth expression is true, the log will reported. + format: str + The format of the message as defined in PEP 3101. + *args + Amaranth values that will be read during simulation and used to format + the message. + src_loc_at: int, optional + How many stack frames below to look for the source location, used to + identify the failing assertion. + """ + + def local_src_loc(src_loc: SrcLoc): + return (os.path.relpath(src_loc[0]), src_loc[1]) + + src_loc = local_src_loc(get_src_loc(src_loc_at + 1)) + + trigger_signal = Signal() + m.d.comb += trigger_signal.eq(trigger) + + record = LogRecord( + logger_name=self.name, level=level, format_str=format, location=src_loc, trigger=trigger_signal + ) + + for arg in args: + sig = Signal.like(arg) + m.d.top_comb += sig.eq(arg) + record.fields.append(sig) + + dependencies = DependencyContext.get() + dependencies.add_dependency(LogKey(), record) + + def debug(self, m: ModuleLike, trigger: ValueLike, format: str, *args, **kwargs): + """Log a message with severity 'DEBUG'. + + See `HardwareLogger.log` function for more details. + """ + self.log(m, logging.DEBUG, trigger, format, *args, **kwargs) + + def info(self, m: ModuleLike, trigger: ValueLike, format: str, *args, **kwargs): + """Log a message with severity 'INFO'. + + See `HardwareLogger.log` function for more details. + """ + self.log(m, logging.INFO, trigger, format, *args, **kwargs) + + def warning(self, m: ModuleLike, trigger: ValueLike, format: str, *args, **kwargs): + """Log a message with severity 'WARNING'. + + See `HardwareLogger.log` function for more details. + """ + self.log(m, logging.WARNING, trigger, format, *args, **kwargs) + + def error(self, m: ModuleLike, trigger: ValueLike, format: str, *args, **kwargs): + """Log a message with severity 'ERROR'. + + This severity level has special semantics. If a log with this serverity + level is triggered, the simulation will be terminated. + + See `HardwareLogger.log` function for more details. + """ + self.log(m, logging.ERROR, trigger, format, *args, **kwargs) + + def assertion(self, m: ModuleLike, value: Value, format: str = "", *args, src_loc_at: int = 0, **kwargs): + """Define an assertion. + + This function might help find some hardware bugs which might otherwise be + hard to detect. If `value` is false, it will terminate the simulation or + it can also be used to turn on a warning LED on a board. + + Internally, this is a convenience wrapper over log.error. + + See `HardwareLogger.log` function for more details. + """ + self.error(m, ~value, format, *args, **kwargs, src_loc_at=src_loc_at + 1) + + +def get_log_records(level: LogLevel, namespace_regexp: str = ".*") -> list[LogRecord]: + """Get log records in for the given severity level and in the + specified namespace. + + This function returns all log records with the severity bigger or equal + to the specified level and belonging to the specified namespace. + + Parameters + ---------- + level: LogLevel + The minimum severity level. + namespace: str, optional + The regexp of the namespace. If not specified, logs from all namespaces + will be processed. + """ + + dependencies = DependencyContext.get() + all_logs = dependencies.get_dependency(LogKey()) + return [rec for rec in all_logs if rec.level >= level and re.search(namespace_regexp, rec.logger_name)] + + +def get_trigger_bit(level: LogLevel, namespace_regexp: str = ".*") -> Value: + """Get a trigger bit for logs of the given severity level and + in the specified namespace. + + The signal returned by this function is high whenever the trigger signal + of any of the records with the severity bigger or equal to the specified + level is high. + + Parameters + ---------- + level: LogLevel + The minimum severity level. + namespace: str, optional + The regexp of the namespace. If not specified, logs from all namespaces + will be processed. + """ + + return reduce(operator.or_, [rec.trigger for rec in get_log_records(level, namespace_regexp)], C(0)) diff --git a/transactron/testing/__init__.py b/transactron/testing/__init__.py index 2ed73b0..bc5d38f 100644 --- a/transactron/testing/__init__.py +++ b/transactron/testing/__init__.py @@ -3,5 +3,5 @@ from .sugar import * # noqa: F401 from .testbenchio import * # noqa: F401 from .profiler import * # noqa: F401 -from .assertion import * # noqa: F401 +from .logging import * # noqa: F401 from transactron.utils import data_layout # noqa: F401 diff --git a/transactron/testing/assertion.py b/transactron/testing/assertion.py deleted file mode 100644 index 19c5a41..0000000 --- a/transactron/testing/assertion.py +++ /dev/null @@ -1,20 +0,0 @@ -from collections.abc import Callable -from typing import Any -from amaranth.sim import Passive, Tick -from transactron.utils import assert_bit, assert_bits - - -__all__ = ["make_assert_handler"] - - -def make_assert_handler(my_assert: Callable[[int, str], Any]): - def assert_handler(): - yield Passive() - while True: - yield Tick("sync_neg") - if not (yield assert_bit()): - for v, (n, i) in assert_bits(): - my_assert((yield v), f"Assertion at {n}:{i}") - yield - - return assert_handler diff --git a/transactron/testing/infrastructure.py b/transactron/testing/infrastructure.py index dc4a540..a769bba 100644 --- a/transactron/testing/infrastructure.py +++ b/transactron/testing/infrastructure.py @@ -13,7 +13,7 @@ from .testbenchio import TestbenchIO from .profiler import profiler_process, Profile from .functions import TestGen -from .assertion import make_assert_handler +from .logging import make_logging_process, parse_logging_level from .gtkw_extension import write_vcd_ext from transactron import Method from transactron.lib import AdapterTrans @@ -263,7 +263,12 @@ def run_simulation(self, module: HasElaborate, max_cycles: float = 10e4, add_tra profiler_process(sim.tested_module.manager.get_dependency(TransactionManagerKey()), profile) ) - sim.add_sync_process(make_assert_handler(self.assertTrue)) + def on_error(): + self.assertTrue(False, "Simulation finished due to an error") + + log_level = parse_logging_level(os.environ["__TRANSACTRON_LOG_LEVEL"]) + log_filter = os.environ["__TRANSACTRON_LOG_FILTER"] + sim.add_sync_process(make_logging_process(log_level, log_filter, on_error)) res = sim.run() diff --git a/transactron/testing/logging.py b/transactron/testing/logging.py new file mode 100644 index 0000000..6a2ad08 --- /dev/null +++ b/transactron/testing/logging.py @@ -0,0 +1,108 @@ +from collections.abc import Callable +from typing import Any +import logging + +from amaranth.sim import Passive, Tick +from transactron.lib import logging as tlog + + +__all__ = ["make_logging_process", "parse_logging_level"] + + +def parse_logging_level(str: str) -> tlog.LogLevel: + """Parse the log level from a string. + + The level can be either a non-negative integer or a string representation + of one of the predefined levels. + + Raises an exception if the level cannot be parsed. + """ + str = str.upper() + names_mapping = logging.getLevelNamesMapping() + if str in names_mapping: + return names_mapping[str] + + # try convert to int + try: + return int(str) + except ValueError: + pass + + raise ValueError("Log level must be either {error, warn, info, debug} or a non-negative integer.") + + +_sim_cycle = 0 + + +class _LogFormatter(logging.Formatter): + """ + Log formatter to provide colors and to inject simulator times into + the log messages. Adapted from https://stackoverflow.com/a/56944256/3638629 + """ + + magenta = "\033[0;35m" + grey = "\033[0;34m" + blue = "\033[0;34m" + yellow = "\033[0;33m" + red = "\033[0;31m" + reset = "\033[0m" + + loglevel2colour = { + logging.DEBUG: grey + "{}" + reset, + logging.INFO: magenta + "{}" + reset, + logging.WARNING: yellow + "{}" + reset, + logging.ERROR: red + "{}" + reset, + } + + def format(self, record: logging.LogRecord): + level_name = self.loglevel2colour[record.levelno].format(record.levelname) + return f"{_sim_cycle} {level_name} {record.name} {record.getMessage()}" + + +def make_logging_process(level: tlog.LogLevel, namespace_regexp: str, on_error: Callable[[], Any]): + combined_trigger = tlog.get_trigger_bit(level, namespace_regexp) + records = tlog.get_log_records(level, namespace_regexp) + + root_logger = logging.getLogger() + ch = logging.StreamHandler() + formatter = _LogFormatter() + ch.setFormatter(formatter) + root_logger.handlers = [ch] + + def handle_logs(): + if not (yield combined_trigger): + return + + for record in records: + if not (yield record.trigger): + continue + + values: list[int] = [] + for field in record.fields: + values.append((yield field)) + + formatted_msg = record.format(*values) + + logger = root_logger.getChild(record.logger_name) + logger.log( + record.level, + "%s:%d] %s", + record.location[0], + record.location[1], + formatted_msg, + ) + + if record.level >= logging.ERROR: + on_error() + + def log_process(): + global _sim_cycle + + yield Passive() + while True: + yield Tick("sync_neg") + yield from handle_logs() + yield + _sim_cycle += 1 + + return log_process diff --git a/transactron/utils/__init__.py b/transactron/utils/__init__.py index 703b2aa..ebf845b 100644 --- a/transactron/utils/__init__.py +++ b/transactron/utils/__init__.py @@ -4,7 +4,6 @@ from .assign import * # noqa: F401 from .amaranth_ext import * # noqa: F401 from .transactron_helpers import * # noqa: F401 -from .assertion import * # noqa: F401 from .dependencies import * # noqa: F401 from .depcache import * # noqa: F401 from .idgen import * # noqa: F401 diff --git a/transactron/utils/assertion.py b/transactron/utils/assertion.py deleted file mode 100644 index b79a74f..0000000 --- a/transactron/utils/assertion.py +++ /dev/null @@ -1,60 +0,0 @@ -from amaranth import * -from amaranth.tracer import get_src_loc -from functools import reduce -import operator -from dataclasses import dataclass -from transactron.utils import SrcLoc -from transactron.utils._typing import ModuleLike, ValueLike -from transactron.utils.dependencies import DependencyContext, ListKey - -__all__ = ["AssertKey", "assertion", "assert_bit", "assert_bits"] - - -@dataclass(frozen=True) -class AssertKey(ListKey[tuple[Signal, SrcLoc]]): - pass - - -def assertion(m: ModuleLike, value: ValueLike, *, src_loc_at: int = 0): - """Define an assertion. - - This function might help find some hardware bugs which might otherwise be - hard to detect. If `value` is false on any assertion, the value returned - from the `assert_bit` function is false. This terminates the simulation, - it can also be used to turn on a warning LED on a board. - - Parameters - ---------- - m: Module - Module in which the assertion is defined. - value : Value - If the value of this Amaranth expression is false, the assertion will - fail. - src_loc_at : int, optional - How many stack frames below to look for the source location, used to - identify the failing assertion. - """ - src_loc = get_src_loc(src_loc_at) - sig = Signal() - m.d.comb += sig.eq(value) - dependencies = DependencyContext.get() - dependencies.add_dependency(AssertKey(), (sig, src_loc)) - - -def assert_bits() -> list[tuple[Signal, SrcLoc]]: - """Gets assertion bits. - - This function returns all the assertion signals created by `assertion`, - together with their source locations. - """ - dependencies = DependencyContext.get() - return dependencies.get_dependency(AssertKey()) - - -def assert_bit() -> Signal: - """Gets assertion bit. - - The signal returned by this function is false if and only if there exists - a false signal among assertion bits created by `assertion`. - """ - return reduce(operator.and_, [a[0] for a in assert_bits()], C(1)) diff --git a/transactron/utils/gen.py b/transactron/utils/gen.py index f877067..daf462c 100644 --- a/transactron/utils/gen.py +++ b/transactron/utils/gen.py @@ -1,5 +1,6 @@ from dataclasses import dataclass, field from dataclasses_json import dataclass_json +from typing import TypeAlias from amaranth import * from amaranth.back import verilog @@ -7,11 +8,10 @@ from transactron.core import TransactionManager, MethodMap, TransactionManagerKey from transactron.lib.metrics import HardwareMetricsManager +from transactron.lib import logging from transactron.utils.dependencies import DependencyContext from transactron.utils.idgen import IdGenerator from transactron.profiler import ProfileData -from transactron.utils._typing import SrcLoc -from transactron.utils.assertion import assert_bits from typing import TYPE_CHECKING @@ -21,11 +21,16 @@ __all__ = [ "MetricLocation", - "AssertLocation", + "GeneratedLog", "GenerationInfo", "generate_verilog", ] +SignalHandle: TypeAlias = list[str] +"""The location of a signal is a list of Verilog identifiers that denote a path +consisting of module names (and the signal name at the end) leading +to the signal wire.""" + @dataclass_json @dataclass @@ -34,13 +39,11 @@ class MetricLocation: Attributes ---------- - regs : dict[str, list[str]] - The location of each register of that metric. The location is a list of - Verilog identifiers that denote a path consiting of modules names - (and the signal name at the end) leading to the register wire. + regs : dict[str, SignalHandle] + The location of each register of that metric. """ - regs: dict[str, list[str]] = field(default_factory=dict) + regs: dict[str, SignalHandle] = field(default_factory=dict) @dataclass_json @@ -79,21 +82,19 @@ class MethodSignalsLocation: @dataclass_json @dataclass -class AssertLocation: - """Information about an assert signal in the generated Verilog code. +class GeneratedLog(logging.LogRecordInfo): + """Information about a log record in the generated Verilog code. Attributes ---------- - location : list[str] - The location of the assert signal. The location is a list of Verilog - identifiers that denote a path consisting of module names (and the - signal name at the end) leading to the signal wire. - src_loc : SrcLoc - Source location of the assertion. + trigger_location : SignalHandle + The location of the trigger signal. + fields_location : list[SignalHandle] + Locations of the log fields. """ - location: list[str] - src_loc: SrcLoc + trigger_location: SignalHandle + fields_location: list[SignalHandle] @dataclass_json @@ -106,16 +107,15 @@ class GenerationInfo: metrics_location : dict[str, MetricInfo] Mapping from a metric name to an object storing Verilog locations of its registers. - asserts : list[AssertLocation] - Locations and metadata for assertion signals. + logs : list[GeneratedLog] + Locations and metadata for all log records. """ metrics_location: dict[str, MetricLocation] transaction_signals_location: dict[int, TransactionSignalsLocation] method_signals_location: dict[int, MethodSignalsLocation] profile_data: ProfileData - metrics_location: dict[str, MetricLocation] - asserts: list[AssertLocation] + logs: list[GeneratedLog] def encode(self, file_name: str): """ @@ -158,7 +158,7 @@ def escape_verilog_identifier(identifier: str) -> str: return identifier -def get_signal_location(signal: Signal, name_map: "SignalDict") -> list[str]: +def get_signal_location(signal: Signal, name_map: "SignalDict") -> SignalHandle: raw_location = name_map[signal] return raw_location @@ -204,13 +204,24 @@ def collect_transaction_method_signals( return (transaction_signals_location, method_signals_location) -def collect_asserts(name_map: "SignalDict") -> list[AssertLocation]: - asserts: list[AssertLocation] = [] - - for v, src_loc in assert_bits(): - asserts.append(AssertLocation(get_signal_location(v, name_map), src_loc)) +def collect_logs(name_map: "SignalDict") -> list[GeneratedLog]: + logs: list[GeneratedLog] = [] + + # Get all records. + for record in logging.get_log_records(0): + trigger_loc = get_signal_location(record.trigger, name_map) + fields_loc = [get_signal_location(field, name_map) for field in record.fields] + log = GeneratedLog( + logger_name=record.logger_name, + level=record.level, + format_str=record.format_str, + location=record.location, + trigger_location=trigger_loc, + fields_location=fields_loc, + ) + logs.append(log) - return asserts + return logs def generate_verilog( @@ -229,7 +240,7 @@ def generate_verilog( transaction_signals_location=transaction_signals, method_signals_location=method_signals, profile_data=profile_data, - asserts=collect_asserts(name_map), + logs=collect_logs(name_map), ) return verilog_text, gen_info