scripts: nrf_profiler: Improve stats calculating script

scripts/nrf_profiler/calc_stats.py

@@ -7,35 +7,40 @@
 
 import argparse
 import logging
+import json
 
 
 def main():
-    parser = argparse.ArgumentParser(description='Calculating stats for events.',
+    parser = argparse.ArgumentParser(description="nRF Profiler event propagation statistics",
                                      allow_abbrev=False)
-    parser.add_argument('dataset_name', help='Name of dataset')
-    parser.add_argument('--start_time', help='Measurement start time[s]')
-    parser.add_argument('--end_time', help='Measurement end time[s]')
-    parser.add_argument('--log', help='Log level')
+    parser.add_argument("dataset_name", help="Name of nRF Profiler dataset")
+    parser.add_argument("test_presets", help="Test preset [*.json file]")
+    parser.add_argument("--start_time", type=float, default=0.0,
+                        help="Measurement start time [s]")
+    parser.add_argument("--end_time", type=float, default=float('inf'),
+                        help="Measurement end time [s]")
+    parser.add_argument("--log", help="Log level")
     args = parser.parse_args()
 
     if args.log is not None:
         log_lvl_number = int(getattr(logging, args.log.upper(), None))
     else:
         log_lvl_number = logging.INFO
 
-    if args.start_time is None:
-        args.start_time = 0
-    else:
-        args.start_time = float(args.start_time)
-
-    if args.end_time is None:
-        args.end_time = float('inf')
-    else:
-        args.end_time = float(args.end_time)
-
-    sn = StatsNordic(args.dataset_name + ".csv", args.dataset_name + ".json",
+    try:
+        with open(args.test_presets, "r") as test_preset_file:
+            test_preset_dict = json.load(test_preset_file)
+    except FileNotFoundError:
+        print("File {} not found".format(args.test_presets))
+        return
+    except Exception as e:
+        print("Exception while opening {}".format(args.test_presets))
+        print(e)
+        return
+
+    sn = StatsNordic("{}.csv".format(args.dataset_name), "{}.json".format(args.dataset_name),
                      log_lvl_number)
-    sn.calculate_stats_preset1(args.start_time, args.end_time)
+    sn.calculate_stats(test_preset_dict, args.start_time, args.end_time)
 
 if __name__ == "__main__":
     main()

scripts/nrf_profiler/stats_nordic.py

@@ -4,184 +4,199 @@
 # SPDX-License-Identifier: LicenseRef-Nordic-5-Clause
 
 from processed_events import ProcessedEvents
-from enum import Enum
+from enum import StrEnum
 import matplotlib.pyplot as plt
 import numpy as np
 import logging
 import os
 
 
-OUTPUT_FOLDER = "data_stats/"
-
-
-class EventState(Enum):
-    SUBMIT = 1
-    PROC_START = 2
-    PROC_END = 3
+OUTPUT_DIR_BASE = "data_stats"
 
+class EventState(StrEnum):
+    SUBMIT = "submit"
+    PROCESSING_START = "processing_start"
+    PROCESSING_END = "processing_end"
 
 class StatsNordic():
     def __init__(self, events_filename, events_types_filename, log_lvl):
-        self.data_name = events_filename.split('.')[0]
+        self.dataset_name = events_filename.split(".")[0]
         self.processed_data = ProcessedEvents()
         self.processed_data.read_data_from_files(events_filename, events_types_filename)
 
-        self.logger = logging.getLogger('Stats Nordic')
+        self.logger = logging.getLogger("Stats Nordic")
         self.logger_console = logging.StreamHandler()
         self.logger.setLevel(log_lvl)
-        self.log_format = logging.Formatter(
-            '[%(levelname)s] %(name)s: %(message)s')
+        self.log_format = logging.Formatter("[%(levelname)s] %(name)s: %(message)s")
         self.logger_console.setFormatter(self.log_format)
         self.logger.addHandler(self.logger_console)
 
-    def calculate_stats_preset1(self, start_meas, end_meas):
-        self.time_between_events("hid_mouse_event_dongle", EventState.SUBMIT,
-                                 "hid_report_sent_event_device", EventState.SUBMIT,
-                                 0.05, start_meas, end_meas)
-        self.time_between_events("hid_mouse_event_dongle", EventState.SUBMIT,
-                                 "hid_report_sent_event_device", EventState.SUBMIT,
-                                 0.05, start_meas, end_meas)
-        self.time_between_events("hid_report_sent_event_dongle", EventState.SUBMIT,
-                                 "hid_report_sent_event_dongle", EventState.SUBMIT,
-                                 0.05, start_meas, end_meas)
-        self.time_between_events("hid_mouse_event_dongle", EventState.SUBMIT,
-                                 "hid_report_sent_event_dongle", EventState.SUBMIT,
-                                 0.05, start_meas, end_meas)
-        self.time_between_events("hid_mouse_event_device", EventState.SUBMIT,
-                                 "hid_mouse_event_dongle", EventState.SUBMIT,
-                                 0.05, start_meas, end_meas)
-        plt.show()
-
-    def _get_timestamps(self, event_name, event_state, start_meas, end_meas):
+    def _get_timestamps(self, event_name, event_state, start_meas=0.0, end_meas=float("inf")):
         event_type_id = self.processed_data.get_event_type_id(event_name)
         if event_type_id is None:
-            self.logger.error("Event name not found: " + event_name)
-            return None
-        if not self.processed_data.is_event_tracked(event_type_id) and event_state != EventState.SUBMIT:
-            self.logger.error("This event is not tracked: " + event_name)
-            return None
-
-        trackings = list(filter(lambda x:
-                      x.submit.type_id == event_type_id,
-                      self.processed_data.tracked_events))
+            raise ValueError("Event not found in dataset: {}".format(event_name))
 
         if not isinstance(event_state, EventState):
-            self.logger.error("Event state should be EventState enum")
-            return None
+            raise ValueError("Invalid EventState: {}".format(event_state))
+
+        if event_state != EventState.SUBMIT:
+            if not self.processed_data.is_event_tracked(event_type_id):
+                raise ValueError("Event not tracked: {}".format(event_name))
+
+        trackings = list(filter(lambda x: x.submit.type_id == event_type_id,
+                                self.processed_data.tracked_events))
 
         if event_state == EventState.SUBMIT:
             timestamps = np.fromiter(map(lambda x: x.submit.timestamp, trackings),
                                      dtype=float)
-        elif event_state == EventState.PROC_START:
+        elif event_state == EventState.PROCESSING_START:
             timestamps = np.fromiter(map(lambda x: x.proc_start_time, trackings),
                                      dtype=float)
-        elif event_state == EventState.PROC_END:
+        elif event_state == EventState.PROCESSING_END:
             timestamps = np.fromiter(map(lambda x: x.proc_end_time, trackings),
                                      dtype=float)
 
-        timestamps = timestamps[np.where((timestamps > start_meas)
-                                         & (timestamps < end_meas))]
+        timestamps = timestamps[np.nonzero((timestamps > start_meas) & (timestamps < end_meas))]
 
         return timestamps
 
-    @staticmethod
-    def calculate_times_between(start_times, end_times):
-        if end_times[0] <= start_times[0]:
+    def _calculate_times_between_ms(self, start_times, end_times):
+        # Number of start times must match the number of end times.
+        # Remove start/end time records to also ensure that start times are before end times.
+        while end_times[0] <= start_times[0]:
+            self.logger.warning("End time[0] <= start time[0], dropping the first end time")
             end_times = end_times[1:]
-        if len(start_times) > len(end_times):
+
+        while len(start_times) > len(end_times):
+            self.logger.warning("Start/end times length mismatch, dropping the last start time")
             start_times = start_times[:-1]
 
-        return (end_times - start_times) * 1000
+        # Convert results to milliseconds
+        times_between = (end_times - start_times) * 1000
+        return times_between, start_times, end_times
+
+    @staticmethod
+    def _get_outlier_filter_mask(measurements, std_factor=3):
+        mean = np.mean(measurements)
+        std = np.std(measurements)
+        limit_min = mean - std_factor * std
+        limit_max = mean + std_factor * std
+
+        return np.nonzero((measurements > limit_min) & (measurements < limit_max))
 
     @staticmethod
-    def prepare_stats_txt(times_between):
-        stats_text = "Max time: "
-        stats_text += "{0:.3f}".format(max(times_between)) + "ms\n"
-        stats_text += "Min time: "
-        stats_text += "{0:.3f}".format(min(times_between)) + "ms\n"
-        stats_text += "Mean time: "
-        stats_text += "{0:.3f}".format(np.mean(times_between)) + "ms\n"
-        stats_text += "Std dev of time: "
-        stats_text += "{0:.3f}".format(np.std(times_between)) + "ms\n"
-        stats_text += "Median time: "
-        stats_text += "{0:.3f}".format(np.median(times_between)) + "ms\n"
-        stats_text += "Number of records: {}".format(len(times_between)) + "\n"
-
-        return stats_text
-
-    def time_between_events(self, start_event_name, start_event_state,
-                            end_event_name, end_event_state, hist_bin_width=0.01,
-                            start_meas=0, end_meas=float('inf')):
-        self.logger.info("Stats calculating: {}->{}".format(start_event_name,
-                                                            end_event_name))
-
-        start_times = self._get_timestamps(start_event_name, start_event_state,
-                                           start_meas, end_meas)
-        end_times = self._get_timestamps(end_event_name, end_event_state,
-                                           start_meas, end_meas)
-
-        if start_times is None or end_times is None:
-            return
-
-        if len(start_times) == 0:
-            self.logger.error("No events logged: " + start_event_name)
-            return
-
-        if len(end_times) == 0:
-            self.logger.error("No events logged: " + end_event_name)
-            return
-
-        if len(start_times) != len(end_times):
-            self.logger.error("Number of start_times and end_times is not equal")
-            self.logger.error("Got {} start_times and {} end_times".format(
-                len(start_times), len(end_times)))
-
-            return
-
-        times_between = self.calculate_times_between(start_times, end_times)
-        stats_text = self.prepare_stats_txt(times_between)
-
-        plt.figure()
-
-        ax = plt.gca()
-        ax.text(0.05,
-                0.95,
-                stats_text,
-                transform=ax.transAxes,
-                fontsize=12,
-                verticalalignment='top',
-                bbox=dict(boxstyle='round',
-                            alpha=0.5,
-                            facecolor='linen'))
-
-        plt.xlabel('Duration[ms]')
-        plt.ylabel('Number of occurrences')
-
-        event_status_str = {
-                        EventState.SUBMIT : "submission",
-                        EventState.PROC_START : "processing start",
-                        EventState.PROC_END : "processing end"
+    def _times_between_to_stats_txt(preset_desc, output_dir, times_between_ms, out_filename="stats",
+                                    logger=None):
+        stats = {
+            "Max" : "{:.3f} ms".format(max(times_between_ms)),
+            "Min" : "{:.3f} ms".format(min(times_between_ms)),
+            "Mean" : "{:.3f} ms".format(np.mean(times_between_ms)),
+            "Std dev" : "{:.3f} ms".format(np.std(times_between_ms)),
+            "Median" : "{:.3f} ms".format(np.median(times_between_ms)),
+            "Number of events" : str(len(times_between_ms))
         }
 
-        title = "From " + start_event_name + ' ' + \
-                event_status_str[start_event_state] + "\nto " + \
-                end_event_name + ' ' + event_status_str[end_event_state] + \
-                ' (' + self.data_name + ')'
-        plt.title(title)
-        plt.hist(times_between, bins = (int)((max(times_between) - min(times_between))
-                                        / hist_bin_width))
+        key_len_max = max(len(k) for k in stats)
+        val_len_max = max(len(v) for v in stats.values())
+
+        out_filepath = os.path.join(output_dir, "{}.txt".format(out_filename))
 
-        plt.yscale('log')
+        with open(out_filepath, "w") as f:
+            f.write("Event propagation times statistics - {}\n".format(preset_desc))
+            for s in stats:
+                f.write("{} {}\n".format(s.ljust(key_len_max), stats[s].rjust(val_len_max)))
+
+        if logger is not None:
+            with open(out_filepath, "r") as f:
+                logger.info(f.read())
+
+    @staticmethod
+    def _times_between_to_histogram(preset_desc, output_dir, times_between_ms,
+                                    out_filename="histogram"):
+        bin_width_ms = 0.01
+
+        plt.xlabel("Time between events [ms]")
+        plt.ylabel("Number of occurrences")
+        plt.title(preset_desc)
         plt.grid(True)
 
-        if end_meas == float('inf'):
-            end_meas_string = 'inf'
+        plt.hist(times_between_ms, bins=np.arange(min(times_between_ms),
+                                                  max(times_between_ms) + bin_width_ms,
+                                                  bin_width_ms))
+
+        plt.savefig(os.path.join(output_dir, "{}.png".format(out_filename)))
+
+        # Save the same plot in log scale
+        plt.yscale("log")
+        plt.savefig(os.path.join(output_dir, "{}_log.png".format(out_filename)))
+
+    @staticmethod
+    def _test_preset_parse_event(event_dict):
+        if event_dict is None:
+            return None, None
+
+        name = event_dict.get("name")
+        state = event_dict.get("state")
+
+        if state is not None:
+            state = EventState(state)
         else:
-            end_meas_string = int(end_meas)
-        dir_name = "{}{}_{}_{}/".format(OUTPUT_FOLDER, self.data_name,
-                                        int(start_meas), end_meas_string)
-        if not os.path.exists(dir_name):
-            os.makedirs(dir_name)
-
-        plt.savefig(dir_name +
-                    title.lower().replace(' ', '_').replace('\n', '_') +'.png')
+            # Assume "submit" event state by default
+            state = EventState.SUBMIT
+
+        return name, state
+
+    def _test_preset_execute(self, test_preset, start_time, end_time):
+        # Load preset description
+        preset_name = test_preset.get("name")
+        start_evt_name, start_evt_state = \
+            StatsNordic._test_preset_parse_event(test_preset.get("start_event"))
+        end_evt_name, end_evt_state = \
+            StatsNordic._test_preset_parse_event(test_preset.get("end_event"))
+
+        # Validate preset description
+        if preset_name is None:
+            raise ValueError("Invalid preset: No preset name")
+        if start_evt_name is None:
+            raise ValueError("Invalid preset: No start event name ({})".format(preset_name))
+        if end_evt_name is None:
+            raise ValueError("Invalid preset: No end event name ({})".format(preset_name))
+
+        preset_desc = "{}: {}({})->{}({})".format(preset_name, start_evt_name, start_evt_state,
+                                                  end_evt_name, end_evt_state)
+        self.logger.info("Execute test preset {}".format(preset_desc))
+
+        # Calculate event propagation times
+        ts_start = self._get_timestamps(start_evt_name, start_evt_state, start_time, end_time)
+        ts_end = self._get_timestamps(end_evt_name, end_evt_state, start_time, end_time)
+        times_between_ms, ts_start, ts_end = self._calculate_times_between_ms(ts_start, ts_end)
+
+        # Prepare output directory
+        output_dir1 = "{}_from_{}_to_{}".format(self.dataset_name, str(start_time), str(end_time))
+        output_dir1 = output_dir1.replace(".", "_")
+
+        output_dir2 = preset_name.lower().replace(" ", "_").replace(".", "_")
+
+        output_dir = os.path.join(OUTPUT_DIR_BASE, output_dir1, output_dir2)
+        os.makedirs(output_dir, exist_ok=True)
+
+        # Filter out outliers
+        mask = StatsNordic._get_outlier_filter_mask(times_between_ms)
+        times_between_ms_no_outliers = times_between_ms[mask]
+
+        # Store results in the output directory
+        StatsNordic._times_between_to_stats_txt(preset_desc, output_dir, times_between_ms,
+                                                logger=self.logger)
+        StatsNordic._times_between_to_histogram(preset_desc + " no outliers", output_dir,
+                                                times_between_ms_no_outliers,
+                                                out_filename="histogram_no_outliers")
+
+        # Display all of the figures to the user
+        plt.show()
+
+    def calculate_stats(self, test_presets, start_time, end_time):
+        for t in test_presets:
+            try:
+                self._test_preset_execute(t, start_time, end_time)
+            except Exception as e:
+                self.logger.warning("Exception: {}".format(e))