twister: get information about memory footprint from build.log

This commit calculate memory footprint from build.log and
proposes an alternative approach to #2465.

Signed-off-by: Katarzyna Giądła <katarzyna.giadla@nordicsemi.no>

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:

scripts/pylib/twister/twisterlib/environment.py

@@ -531,7 +531,9 @@ structure in the main Zephyr tree: boards/<arch>/<board_name>/""")
              "'--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/<arch>/<board_name>/""")
              "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

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)
+            used_ram = instance.metrics.get ("used_ram", 0)
-            rom_size  = instance.metrics.get("rom_size",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:
+            if used_ram:
-                suite["ram_size"] = ram_size
+                suite["used_ram"] = used_ram
-            if rom_size:
+            if used_rom:
-                suite["rom_size"] = rom_size
+                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),
+        interesting_metrics = [("used_ram", int, True),
-                               ("rom_size", int, True)]
+                               ("used_rom", int, True)]
 
         if not os.path.exists(filename):
             logger.error("Cannot compare metrics, %s not found" % filename)

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["used_ram"] = 0
-            instance.metrics["rom_size"] = 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":
+            if not instance.platform.type in ["native", "qemu"]:
-                size_calc = instance.calculate_sizes()
+                generate_warning = bool(instance.platform.type == "mcu")
-                instance.metrics["ram_size"] = size_calc.get_ram_size()
+                size_calc = instance.calculate_sizes(from_buildlog=from_buildlog, generate_warning=generate_warning)
-                instance.metrics["rom_size"] = size_calc.get_rom_size()
+                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["used_ram"] = 0
-                instance.metrics["rom_size"] = 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:

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
+        @param elf_filename (str) Path to the output binary
-            The <filename> is parsed by objdump to determine section sizes
+            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
+        self.elf_filename = elf_filename
-        with open(filename, "rb") as f:
+        self.buildlog_filename = buildlog_filepath
-            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.sections = []
-        self.rom_size = 0
+        self.used_rom = 0
-        self.ram_size = 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 """
+        """ELF file is analyzed, even if the option to read memory
-        objdump_command = "objdump -h " + self.filename
+        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
+            # If build.log file exists, check errors (unrecognized sections
-                stype = "alloc"
+            # in ELF file).
-            elif name in SizeCalculator.rw_sections:
+            if self.buildlog_filename:
-                self.ram_size += size
+                if name in SizeCalculator.alloc_sections or\
-                self.rom_size += size
+                    SizeCalculator.rw_sections or\
-                stype = "rw"
+                    SizeCalculator.ro_sections:
-            elif name in SizeCalculator.ro_sections:
+                    continue
-                self.rom_size += size
+                else:
-                if not self.is_xip:
+                    stype = "unknown"
-                    self.ram_size += size
+                    if name not in self.extra_sections:
-                stype = "ro"
+                        recognized = False
             else:
-                stype = "unknown"
+                if name in SizeCalculator.alloc_sections:
-                if name not in self.extra_sections:
+                    self.used_ram += size
-                    recognized = False
+                    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])

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 "<TestSuite %s on %s>" % (self.testsuite.name, self.platform.name)

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['used_ram'] = ts.get("used_ram", 0)
-                instance.metrics['rom_size']  = ts.get("rom_size",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")