diff --git a/scripts/ci/test_plan.py b/scripts/ci/test_plan.py index 537194d4d32..0a420fe36a3 100755 --- a/scripts/ci/test_plan.py +++ b/scripts/ci/test_plan.py @@ -370,7 +370,7 @@ if __name__ == "__main__": logging.info(f'Total nodes to launch: {nodes}') header = ['test', 'arch', 'platform', 'status', 'extra_args', 'handler', - 'handler_time', 'ram_size', 'rom_size'] + 'handler_time', 'used_ram', 'used_rom'] # write plan if dup_free: diff --git a/scripts/pylib/twister/twisterlib/environment.py b/scripts/pylib/twister/twisterlib/environment.py index 1d5569acdcf..cab2de0308e 100644 --- a/scripts/pylib/twister/twisterlib/environment.py +++ b/scripts/pylib/twister/twisterlib/environment.py @@ -531,7 +531,9 @@ structure in the main Zephyr tree: boards///""") "'--ninja' argument (to use Ninja build generator).") parser.add_argument( - "--show-footprint", action="store_true", + "--show-footprint", + action="store_true", + required = "--footprint-from-buildlog" in sys.argv, help="Show footprint statistics and deltas since last release." ) @@ -618,6 +620,12 @@ structure in the main Zephyr tree: boards///""") "stdout detailing RAM/ROM sizes on the specified filenames. " "All other command line arguments ignored.") + parser.add_argument( + "--footprint-from-buildlog", + action = "store_true", + help="Get information about memory footprint from generated build.log. " + "Requires using --show-footprint option.") + options = parser.parse_args(args) # Very early error handling diff --git a/scripts/pylib/twister/twisterlib/reports.py b/scripts/pylib/twister/twisterlib/reports.py index c9686e2a6df..03427ff8e0e 100644 --- a/scripts/pylib/twister/twisterlib/reports.py +++ b/scripts/pylib/twister/twisterlib/reports.py @@ -250,8 +250,10 @@ class Reporting: device_log = os.path.join(instance.build_dir, "device.log") handler_time = instance.metrics.get('handler_time', 0) - ram_size = instance.metrics.get ("ram_size", 0) - rom_size = instance.metrics.get("rom_size",0) + used_ram = instance.metrics.get ("used_ram", 0) + used_rom = instance.metrics.get("used_rom",0) + available_ram = instance.metrics.get("available_ram", 0) + available_rom = instance.metrics.get("available_rom", 0) suite = { "name": instance.testsuite.name, "arch": instance.platform.arch, @@ -264,13 +266,17 @@ class Reporting: if instance.status != 'filtered': suite["runnable"] = instance.run - if ram_size: - suite["ram_size"] = ram_size - if rom_size: - suite["rom_size"] = rom_size + if used_ram: + suite["used_ram"] = used_ram + if used_rom: + suite["used_rom"] = used_rom suite['retries'] = instance.retries + if available_ram: + suite["available_ram"] = available_ram + if available_rom: + suite["available_rom"] = available_rom if instance.status in ["error", "failed"]: suite['status'] = instance.status suite["reason"] = instance.reason @@ -341,8 +347,8 @@ class Reporting: def compare_metrics(self, filename): # name, datatype, lower results better - interesting_metrics = [("ram_size", int, True), - ("rom_size", int, True)] + interesting_metrics = [("used_ram", int, True), + ("used_rom", int, True)] if not os.path.exists(filename): logger.error("Cannot compare metrics, %s not found" % filename) diff --git a/scripts/pylib/twister/twisterlib/runner.py b/scripts/pylib/twister/twisterlib/runner.py index 06a6043efe0..3286b73a2f9 100644 --- a/scripts/pylib/twister/twisterlib/runner.py +++ b/scripts/pylib/twister/twisterlib/runner.py @@ -22,6 +22,7 @@ from twisterlib.cmakecache import CMakeCache from twisterlib.environment import canonical_zephyr_base from twisterlib.log_helper import log_command from domains import Domains +from twisterlib.testinstance import TestInstance logger = logging.getLogger('twister') logger.setLevel(logging.DEBUG) @@ -840,31 +841,36 @@ class ProjectBuilder(FilterBuilder): sys.stdout.flush() - def gather_metrics(self, instance): + def gather_metrics(self, instance: TestInstance): if self.options.enable_size_report and not self.options.cmake_only: - self.calc_one_elf_size(instance) + self.calc_size(instance=instance, from_buildlog=self.options.footprint_from_buildlog) else: - instance.metrics["ram_size"] = 0 - instance.metrics["rom_size"] = 0 + instance.metrics["used_ram"] = 0 + instance.metrics["used_rom"] = 0 + instance.metrics["available_rom"] = 0 + instance.metrics["available_ram"] = 0 instance.metrics["unrecognized"] = [] @staticmethod - def calc_one_elf_size(instance): + def calc_size(instance: TestInstance, from_buildlog: bool): if instance.status not in ["error", "failed", "skipped"]: - if instance.platform.type != "native": - size_calc = instance.calculate_sizes() - instance.metrics["ram_size"] = size_calc.get_ram_size() - instance.metrics["rom_size"] = size_calc.get_rom_size() + if not instance.platform.type in ["native", "qemu"]: + generate_warning = bool(instance.platform.type == "mcu") + size_calc = instance.calculate_sizes(from_buildlog=from_buildlog, generate_warning=generate_warning) + instance.metrics["used_ram"] = size_calc.get_used_ram() + instance.metrics["used_rom"] = size_calc.get_used_rom() + instance.metrics["available_rom"] = size_calc.get_available_rom() + instance.metrics["available_ram"] = size_calc.get_available_ram() instance.metrics["unrecognized"] = size_calc.unrecognized_sections() else: - instance.metrics["ram_size"] = 0 - instance.metrics["rom_size"] = 0 + instance.metrics["used_ram"] = 0 + instance.metrics["used_rom"] = 0 + instance.metrics["available_rom"] = 0 + instance.metrics["available_ram"] = 0 instance.metrics["unrecognized"] = [] - instance.metrics["handler_time"] = instance.execution_time - class TwisterRunner: def __init__(self, instances, suites, env=None) -> None: diff --git a/scripts/pylib/twister/twisterlib/size_calc.py b/scripts/pylib/twister/twisterlib/size_calc.py index b0dfd802eb9..b670adf0f60 100644 --- a/scripts/pylib/twister/twisterlib/size_calc.py +++ b/scripts/pylib/twister/twisterlib/size_calc.py @@ -6,8 +6,14 @@ import subprocess import sys +import os +import re +import typing +import logging from twisterlib.error import TwisterRuntimeError +logger = logging.getLogger('twister') +logger.setLevel(logging.DEBUG) class SizeCalculator: alloc_sections = [ @@ -91,51 +97,42 @@ class SizeCalculator: "ppp_protocol_handler_area", ] - def __init__(self, filename, extra_sections): + # Variable below is stored for calculating size using build.log + USEFUL_LINES_AMOUNT = 4 + + def __init__(self, elf_filename: str,\ + extra_sections: typing.List[str],\ + buildlog_filepath: str = '',\ + generate_warning: bool = True): """Constructor - @param filename Path to the output binary - The is parsed by objdump to determine section sizes + @param elf_filename (str) Path to the output binary + parsed by objdump to determine section sizes. + @param extra_sections (list[str]) List of extra, + unexpected sections, which Twister should not + report as error and not include in the + size calculation. + @param buildlog_filepath (str, default: '') Path to the + output build.log + @param generate_warning (bool, default: True) Twister should + (or not) warning about missing the information about + footprint. """ - # Make sure this is an ELF binary - with open(filename, "rb") as f: - magic = f.read(4) - - try: - if magic != b'\x7fELF': - raise TwisterRuntimeError("%s is not an ELF binary" % filename) - except Exception as e: - print(str(e)) - sys.exit(2) - - # Search for CONFIG_XIP in the ELF's list of symbols using NM and AWK. - # GREP can not be used as it returns an error if the symbol is not - # found. - is_xip_command = "nm " + filename + \ - " | awk '/CONFIG_XIP/ { print $3 }'" - is_xip_output = subprocess.check_output( - is_xip_command, shell=True, stderr=subprocess.STDOUT).decode( - "utf-8").strip() - try: - if is_xip_output.endswith("no symbols"): - raise TwisterRuntimeError("%s has no symbol information" % filename) - except Exception as e: - print(str(e)) - sys.exit(2) - - self.is_xip = (len(is_xip_output) != 0) - - self.filename = filename + self.elf_filename = elf_filename + self.buildlog_filename = buildlog_filepath self.sections = [] - self.rom_size = 0 - self.ram_size = 0 + self.used_rom = 0 + self.used_ram = 0 + self.available_ram = 0 + self.available_rom = 0 self.extra_sections = extra_sections + self.is_xip = True + self.generate_warning = generate_warning self._calculate_sizes() - def size_report(self): - print(self.filename) + print(self.elf_filename) print("SECTION NAME VMA LMA SIZE HEX SZ TYPE") for v in self.sections: print("%-17s 0x%08x 0x%08x %8d 0x%05x %-7s" % @@ -143,22 +140,22 @@ class SizeCalculator: v["type"])) print("Totals: %d bytes (ROM), %d bytes (RAM)" % - (self.rom_size, self.ram_size)) + (self.used_rom, self.used_ram)) print("") - def get_ram_size(self): + def get_used_ram(self): """Get the amount of RAM the application will use up on the device @return amount of RAM, in bytes """ - return self.ram_size + return self.used_ram - def get_rom_size(self): + def get_used_rom(self): """Get the size of the data that this application uses on device's flash @return amount of ROM, in bytes """ - return self.rom_size + return self.used_rom def unrecognized_sections(self): """Get a list of sections inside the binary that weren't recognized @@ -171,9 +168,63 @@ class SizeCalculator: slist.append(v["name"]) return slist + def get_available_ram(self) -> int: + """Get the total available RAM. + + @return total available RAM, in bytes (int) + """ + return self.available_ram + + def get_available_rom(self) -> int: + """Get the total available ROM. + + @return total available ROM, in bytes (int) + """ + return self.available_rom + def _calculate_sizes(self): - """ Calculate RAM and ROM usage by section """ - objdump_command = "objdump -h " + self.filename + """ELF file is analyzed, even if the option to read memory + footprint from the build.log file is set. + This is to detect potential problems contained in + unrecognized sections of the file. + """ + self._analyze_elf_file() + if self.buildlog_filename.endswith("build.log"): + self._get_footprint_from_buildlog() + + def _check_elf_file(self) -> None: + # Make sure this is an ELF binary + with open(self.elf_filename, "rb") as f: + magic = f.read(4) + + try: + if magic != b'\x7fELF': + raise TwisterRuntimeError("%s is not an ELF binary" % self.elf_filename) + except Exception as e: + print(str(e)) + sys.exit(2) + + def _check_is_xip(self) -> None: + # Search for CONFIG_XIP in the ELF's list of symbols using NM and AWK. + # GREP can not be used as it returns an error if the symbol is not + # found. + is_xip_command = "nm " + self.elf_filename + \ + " | awk '/CONFIG_XIP/ { print $3 }'" + is_xip_output = subprocess.check_output( + is_xip_command, shell=True, stderr=subprocess.STDOUT).decode( + "utf-8").strip() + try: + if is_xip_output.endswith("no symbols"): + raise TwisterRuntimeError("%s has no symbol information" % self.elf_filename) + except Exception as e: + print(str(e)) + sys.exit(2) + + self.is_xip = (len(is_xip_output) != 0) + + def _get_info_elf_sections(self) -> None: + """Calculate RAM and ROM usage and information about issues by section""" + objdump_command = "objdump -h " + self.elf_filename objdump_output = subprocess.check_output( objdump_command, shell=True).decode("utf-8").splitlines() @@ -204,23 +255,208 @@ class SizeCalculator: # Add section to memory use totals (for both non-XIP and XIP scenarios) # Unrecognized section names are not included in the calculations. recognized = True - if name in SizeCalculator.alloc_sections: - self.ram_size += size - stype = "alloc" - elif name in SizeCalculator.rw_sections: - self.ram_size += size - self.rom_size += size - stype = "rw" - elif name in SizeCalculator.ro_sections: - self.rom_size += size - if not self.is_xip: - self.ram_size += size - stype = "ro" + + # If build.log file exists, check errors (unrecognized sections + # in ELF file). + if self.buildlog_filename: + if name in SizeCalculator.alloc_sections or\ + SizeCalculator.rw_sections or\ + SizeCalculator.ro_sections: + continue + else: + stype = "unknown" + if name not in self.extra_sections: + recognized = False else: - stype = "unknown" - if name not in self.extra_sections: - recognized = False + if name in SizeCalculator.alloc_sections: + self.used_ram += size + stype = "alloc" + elif name in SizeCalculator.rw_sections: + self.used_ram += size + self.used_rom += size + stype = "rw" + elif name in SizeCalculator.ro_sections: + self.used_rom += size + if not self.is_xip: + self.used_ram += size + stype = "ro" + else: + stype = "unknown" + if name not in self.extra_sections: + recognized = False self.sections.append({"name": name, "load_addr": load_addr, "size": size, "virt_addr": virt_addr, "type": stype, "recognized": recognized}) + + def _analyze_elf_file(self) -> None: + self._check_elf_file() + self._check_is_xip() + self._get_info_elf_sections() + + def _get_buildlog_file_content(self) -> typing.List[str]: + """Get content of the build.log file. + + @return Content of the build.log file (list[str]) + """ + if os.path.exists(path=self.buildlog_filename): + with open(file=self.buildlog_filename, mode='r') as file: + file_content = file.readlines() + else: + if self.generate_warning: + logger.error(msg=f"Incorrect path to build.log file to analyze footprints. Please check the path {self.buildlog_filename}.") + file_content = [] + return file_content + + def _find_offset_of_last_pattern_occurrence(self, file_content: typing.List[str]) -> int: + """Find the offset from which the information about the memory footprint is read. + + @param file_content (list[str]) Content of build.log. + @return Offset with information about the memory footprint (int) + """ + result = -1 + if len(file_content) == 0: + logger.warning("Build.log file is empty.") + else: + # Pattern to first line with information about memory footprint + PATTERN_SEARCHED_LINE = "Memory region" + # Check the file in reverse order. + for idx, line in enumerate(reversed(file_content)): + # Condition is fulfilled if the pattern matches with the start of the line. + if re.match(pattern=PATTERN_SEARCHED_LINE, string=line): + result = idx + 1 + break + # If the file does not contain information about memory footprint, the warning is raised. + if result == -1: + logger.warning(msg=f"Information about memory footprint for this test configuration is not found. Please check file {self.buildlog_filename}.") + return result + + def _get_lines_with_footprint(self, start_offset: int, file_content: typing.List[str]) -> typing.List[str]: + """Get lines from the file with a memory footprint. + + @param start_offset (int) Offset with the first line of the information about memory footprint. + @param file_content (list[str]) Content of the build.log file. + @return Lines with information about memory footprint (list[str]) + """ + if len(file_content) == 0: + result = [] + else: + if start_offset > len(file_content) or start_offset <= 0: + info_line_idx_start = len(file_content) - 1 + else: + info_line_idx_start = len(file_content) - start_offset + + info_line_idx_stop = info_line_idx_start + self.USEFUL_LINES_AMOUNT + if info_line_idx_stop > len(file_content): + info_line_idx_stop = len(file_content) + + result = file_content[info_line_idx_start:info_line_idx_stop] + return result + + def _clear_whitespaces_from_lines(self, text_lines: typing.List[str]) -> typing.List[str]: + """Clear text lines from whitespaces. + + @param text_lines (list[str]) Lines with useful information. + @return Cleared text lines with information (list[str]) + """ + return [line.strip("\n").rstrip("%") for line in text_lines] if text_lines else [] + + def _divide_text_lines_into_columns(self, text_lines: typing.List[str]) -> typing.List[typing.List[str]]: + """Divide lines of text into columns. + + @param lines (list[list[str]]) Lines with information about memory footprint. + @return Lines divided into columns (list[list[str]]) + """ + if text_lines: + result = [] + PATTERN_SPLIT_COLUMNS = " +" + for line in text_lines: + line = [column.rstrip(":") for column in re.split(pattern=PATTERN_SPLIT_COLUMNS, string=line)] + result.append(list(filter(None, line))) + else: + result = [[]] + + return result + + def _unify_prefixes_on_all_values(self, data_lines: typing.List[typing.List[str]]) -> typing.List[typing.List[str]]: + """Convert all values in the table to unified order of magnitude. + + @param data_lines (list[list[str]]) Lines with information about memory footprint. + @return Lines with unified values (list[list[str]]) + """ + if len(data_lines) != self.USEFUL_LINES_AMOUNT: + data_lines = [[]] + if self.generate_warning: + logger.warning(msg=f"Incomplete information about memory footprint. Please check file {self.buildlog_filename}") + else: + for idx, line in enumerate(data_lines): + # Line with description of the columns + if idx == 0: + continue + line_to_replace = list(map(self._binary_prefix_converter, line)) + data_lines[idx] = line_to_replace + + return data_lines + + def _binary_prefix_converter(self, value: str) -> str: + """Convert specific value to particular prefix. + + @param value (str) Value to convert. + @return Converted value to output prefix (str) + """ + PATTERN_VALUE = r"([0-9]?\s.?B\Z)" + + if not re.search(pattern=PATTERN_VALUE, string=value): + converted_value = value.rstrip() + else: + PREFIX_POWER = {'B': 0, 'KB': 10, 'MB': 20, 'GB': 30} + DEFAULT_DATA_PREFIX = 'B' + + data_parts = value.split() + numeric_value = int(data_parts[0]) + unit = data_parts[1] + shift = PREFIX_POWER.get(unit, 0) - PREFIX_POWER.get(DEFAULT_DATA_PREFIX, 0) + unit_predictor = pow(2, shift) + converted_value = str(numeric_value * unit_predictor) + return converted_value + + def _create_data_table(self) -> typing.List[typing.List[str]]: + """Create table with information about memory footprint. + + @return Table with information about memory usage (list[list[str]]) + """ + file_content = self._get_buildlog_file_content() + data_line_start_idx = self._find_offset_of_last_pattern_occurrence(file_content=file_content) + + if data_line_start_idx < 0: + data_from_content = [[]] + else: + # Clean lines and separate information to columns + information_lines = self._get_lines_with_footprint(start_offset=data_line_start_idx, file_content=file_content) + information_lines = self._clear_whitespaces_from_lines(text_lines=information_lines) + data_from_content = self._divide_text_lines_into_columns(text_lines=information_lines) + data_from_content = self._unify_prefixes_on_all_values(data_lines=data_from_content) + + return data_from_content + + def _get_footprint_from_buildlog(self) -> None: + """Get memory footprint from build.log""" + data_from_file = self._create_data_table() + + if data_from_file == [[]] or not data_from_file: + self.used_ram = 0 + self.used_rom = 0 + self.available_ram = 0 + self.available_rom = 0 + if self.generate_warning: + logger.warning(msg=f"Missing information about memory footprint. Check file {self.buildlog_filename}.") + else: + ROW_RAM_IDX = 2 + ROW_ROM_IDX = 1 + COLUMN_USED_SIZE_IDX = 1 + COLUMN_AVAILABLE_SIZE_IDX = 2 + + self.used_ram = int(data_from_file[ROW_RAM_IDX][COLUMN_USED_SIZE_IDX]) + self.used_rom = int(data_from_file[ROW_ROM_IDX][COLUMN_USED_SIZE_IDX]) + self.available_ram = int(data_from_file[ROW_RAM_IDX][COLUMN_AVAILABLE_SIZE_IDX]) + self.available_rom = int(data_from_file[ROW_ROM_IDX][COLUMN_AVAILABLE_SIZE_IDX]) diff --git a/scripts/pylib/twister/twisterlib/testinstance.py b/scripts/pylib/twister/twisterlib/testinstance.py index ec94e1cab71..4df2469d619 100644 --- a/scripts/pylib/twister/twisterlib/testinstance.py +++ b/scripts/pylib/twister/twisterlib/testinstance.py @@ -16,7 +16,6 @@ from twisterlib.error import BuildError from twisterlib.size_calc import SizeCalculator from twisterlib.handlers import Handler, SimulationHandler, BinaryHandler, QEMUHandler, DeviceHandler, SUPPORTED_SIMS - logger = logging.getLogger('twister') logger.setLevel(logging.DEBUG) @@ -236,7 +235,7 @@ class TestInstance: return content - def calculate_sizes(self): + def calculate_sizes(self, from_buildlog: bool = False, generate_warning: bool = True) -> SizeCalculator: """Get the RAM/ROM sizes of a test case. This can only be run after the instance has been executed by @@ -244,13 +243,31 @@ class TestInstance: @return A SizeCalculator object """ + elf_filepath = self.get_elf_file() + buildlog_filepath = self.get_buildlog_file() if from_buildlog else '' + return SizeCalculator(elf_filename=elf_filepath, + extra_sections=self.testsuite.extra_sections, + buildlog_filepath=buildlog_filepath, + generate_warning=generate_warning) + + def get_elf_file(self) -> str: fns = glob.glob(os.path.join(self.build_dir, "zephyr", "*.elf")) fns.extend(glob.glob(os.path.join(self.build_dir, "zephyr", "*.exe"))) fns = [x for x in fns if '_pre' not in x] if len(fns) != 1: raise BuildError("Missing/multiple output ELF binary") + return fns[0] - return SizeCalculator(fns[0], self.testsuite.extra_sections) + def get_buildlog_file(self) -> str: + """Get path to build.log file. + + @raises BuildError: Incorrect amount (!=1) of build logs. + @return: Path to build.log (str). + """ + buildlog_paths = glob.glob(os.path.join(self.build_dir, "build.log")) + if len(buildlog_paths) != 1: + raise BuildError("Missing/multiple build.log file.") + return buildlog_paths[0] def __repr__(self): return "" % (self.testsuite.name, self.platform.name) diff --git a/scripts/pylib/twister/twisterlib/testplan.py b/scripts/pylib/twister/twisterlib/testplan.py index 105689de9f5..8e826040faf 100755 --- a/scripts/pylib/twister/twisterlib/testplan.py +++ b/scripts/pylib/twister/twisterlib/testplan.py @@ -518,8 +518,10 @@ class TestPlan: ) instance.metrics['handler_time'] = ts.get('execution_time', 0) - instance.metrics['ram_size'] = ts.get("ram_size", 0) - instance.metrics['rom_size'] = ts.get("rom_size",0) + instance.metrics['used_ram'] = ts.get("used_ram", 0) + instance.metrics['used_rom'] = ts.get("used_rom",0) + instance.metrics['available_ram'] = ts.get('available_ram', 0) + instance.metrics['available_rom'] = ts.get('available_rom', 0) status = ts.get('status', None) reason = ts.get("reason", "Unknown")