From 30696d92fff568c68475f578b366d8b820ed8bb9 Mon Sep 17 00:00:00 2001 From: Théo de la Hogue Date: Fri, 21 Jun 2024 03:15:05 +0200 Subject: Moving time assessment into a decorator. --- src/argaze/ArFeatures.py | 96 ++++-------------- src/argaze/ArUcoMarker/ArUcoCamera.py | 1 + src/argaze/DataFeatures.py | 181 +++++++++++++++++++++------------- 3 files changed, 136 insertions(+), 142 deletions(-) diff --git a/src/argaze/ArFeatures.py b/src/argaze/ArFeatures.py index 46884e6..d1fbfad 100644 --- a/src/argaze/ArFeatures.py +++ b/src/argaze/ArFeatures.py @@ -315,6 +315,7 @@ class ArLayer(DataFeatures.SharedObject, DataFeatures.PipelineStepObject): self.__aoi_scan_path.expected_aoi = expected_aoi @DataFeatures.PipelineStepMethod + @DataFeatures.PipelineStepExecutionTime def look(self, gaze_movement: GazeFeatures.GazeMovement = None): """ Project timestamped gaze movement into layer. @@ -697,6 +698,7 @@ class ArFrame(DataFeatures.SharedObject, DataFeatures.PipelineStepObject): return d @DataFeatures.PipelineStepMethod + @DataFeatures.PipelineStepExecutionTime def look(self, timestamped_gaze_position: GazeFeatures.GazePosition = GazeFeatures.GazePosition()): """ Project timestamped gaze position into frame. @@ -1389,6 +1391,7 @@ class ArCamera(ArFrame): raise NotImplementedError('watch() method not implemented') @DataFeatures.PipelineStepMethod + @DataFeatures.PipelineStepExecutionTime def look(self, timestamped_gaze_position: GazeFeatures.GazePosition): """Project timestamped gaze position into each scene frames. @@ -1442,6 +1445,7 @@ class ArCamera(ArFrame): pass @DataFeatures.PipelineStepMethod + @DataFeatures.PipelineStepExecutionTime def map(self): """Project camera frame background into scene frames background. @@ -1500,14 +1504,6 @@ class ArContext(DataFeatures.PipelineStepObject): self.__pipeline = None self.__exceptions = DataFeatures.TimestampedExceptions() - # Init gaze position processing assessment - self.__process_gaze_position_chrono = UtilsFeatures.TimeProbe() - self.__process_gaze_position_frequency = 0 - - # Init camera image processing assessment - self.__process_camera_image_chrono = UtilsFeatures.TimeProbe() - self.__process_camera_image_frequency = 0 - # Init protected attributes self._stop_event = threading.Event() self._pause_event = threading.Event() @@ -1543,9 +1539,6 @@ class ArContext(DataFeatures.PipelineStepObject): def __enter__(self): """Enter into ArContext.""" - self.__process_gaze_position_chrono.start() - self.__process_camera_image_chrono.start() - return self @DataFeatures.PipelineStepExit @@ -1558,14 +1551,6 @@ class ArContext(DataFeatures.PipelineStepObject): logging.debug('ArContext._process_gaze_position %s', self.name) - # Assess gaze position processing frequency - lap_time, nb_laps, elapsed_time = self.__process_gaze_position_chrono.lap() - - if elapsed_time > 1e3: - - self.__process_gaze_position_frequency = nb_laps - self.__process_gaze_position_chrono.restart() - if issubclass(type(self.__pipeline), ArFrame): #try: @@ -1588,41 +1573,11 @@ class ArContext(DataFeatures.PipelineStepObject): raise (TypeError('Pipeline is not ArFrame instance.')) - def process_gaze_position_performance(self) -> tuple[float, float]: - """Get process gaze position time and frequency. - - Returns: - time: how many time the execution of pipeline look method took. - frequency: how many times persecond the pipeline look method is called. - """ - - look_time = 0. - - if issubclass(type(self.__pipeline), ArFrame): - - try: - - look_time = self.__pipeline.execution_times['look'] - - except KeyError: - - look_time = 0. - - return look_time, self.__process_gaze_position_frequency - def _process_camera_image(self, timestamp: int | float, image: numpy.array): """Request pipeline to process new camera image at a timestamp.""" logging.debug('ArContext._process_camera_image %s', self.name) - # Assess camera image processing frequency - lap_time, nb_laps, elapsed_time = self.__process_camera_image_chrono.lap() - - if elapsed_time > 1e3: - - self.__process_camera_image_frequency = nb_laps - self.__process_camera_image_chrono.restart() - if issubclass(type(self.__pipeline), ArCamera): height, width, _ = image.shape @@ -1664,29 +1619,8 @@ class ArContext(DataFeatures.PipelineStepObject): raise (TypeError('Pipeline is not ArCamera instance.')) - def process_camera_image_performance(self) -> tuple[float, float]: - """Get process camera image time and frequency. - - Returns: - time: how many time the execution of pipeline watch method took. - frequency: how many times persecond the pipeline watch method is called. - """ - - watch_time = 0. - - if issubclass(type(self.__pipeline), ArCamera): - - try: - - watch_time = self.__pipeline.execution_times['watch'] - - except KeyError: - - watch_time = 0. - - return watch_time, self.__process_camera_image_frequency - @DataFeatures.PipelineStepImage + @DataFeatures.PipelineStepExecutionTime def image(self, draw_pipeline: bool = True, draw_times: bool = True, draw_exceptions: bool = True): """ Get pipeline image with execution information. @@ -1718,29 +1652,39 @@ class ArContext(DataFeatures.PipelineStepObject): if draw_times: + # Draw frame timestamp if image.is_timestamped(): info_stack += 1 cv2.putText(image, f'Frame at {image.timestamp}ms', (20, info_stack * 40), cv2.FONT_HERSHEY_SIMPLEX, 1, (255, 255, 255), 1, cv2.LINE_AA) + # Draw watch time if relevant if issubclass(type(self.__pipeline), ArCamera): - time, frequency = self.process_camera_image_performance() + time, frequency = self.__pipeline.execution_info('watch') info_stack += 1 - cv2.putText(image, f'Watch {int(time)}ms at {frequency}Hz', (20, info_stack * 40), cv2.FONT_HERSHEY_SIMPLEX, 1, (255, 255, 255), 1, cv2.LINE_AA) + cv2.putText(image, f'Watch {time*1e3:.0f}ms at {frequency:.0f}Hz', (20, info_stack * 40), cv2.FONT_HERSHEY_SIMPLEX, 1, (255, 255, 255), 1, cv2.LINE_AA) + # Draw gaze position timestamp if last_position is not None: info_stack += 1 - cv2.putText(image, f'Position at {last_position.timestamp}ms', (20, info_stack * 40), cv2.FONT_HERSHEY_SIMPLEX, 1, (255, 255, 255), 1, cv2.LINE_AA) + cv2.putText(image, f'Position at {last_position.timestamp:.3f}ms', (20, info_stack * 40), cv2.FONT_HERSHEY_SIMPLEX, 1, (255, 255, 255), 1, cv2.LINE_AA) + # Draw look time if relevant if issubclass(type(self.__pipeline), ArFrame): - time, frequency = self.process_gaze_position_performance() + time, frequency = self.__pipeline.execution_info('look') info_stack += 1 - cv2.putText(image, f'Look {time:.2f}ms at {frequency}Hz', (20, info_stack * 40), cv2.FONT_HERSHEY_SIMPLEX, 1, (255, 255, 255), 1, cv2.LINE_AA) + cv2.putText(image, f'Look {time*1e3:.2f}ms at {frequency:.0f}Hz', (20, info_stack * 40), cv2.FONT_HERSHEY_SIMPLEX, 1, (255, 255, 255), 1, cv2.LINE_AA) + + # Draw visualization time + time, frequency = time, frequency = self.execution_info('image') + + info_stack += 1 + cv2.putText(image, f'Visualization {time*1e3:.0f}ms at {frequency:.0f}Hz', (20, info_stack * 40), cv2.FONT_HERSHEY_SIMPLEX, 1, (255, 255, 255), 1, cv2.LINE_AA) if draw_exceptions: diff --git a/src/argaze/ArUcoMarker/ArUcoCamera.py b/src/argaze/ArUcoMarker/ArUcoCamera.py index d095f7b..215fec6 100644 --- a/src/argaze/ArUcoMarker/ArUcoCamera.py +++ b/src/argaze/ArUcoMarker/ArUcoCamera.py @@ -113,6 +113,7 @@ class ArUcoCamera(ArFeatures.ArCamera): self._update_expected_and_excluded_aoi() @DataFeatures.PipelineStepMethod + @DataFeatures.PipelineStepExecutionTime def watch(self, image: DataFeatures.TimestampedImage): """Detect environment aruco markers from image and project scenes into camera frame.""" diff --git a/src/argaze/DataFeatures.py b/src/argaze/DataFeatures.py index 946b289..0d1e351 100644 --- a/src/argaze/DataFeatures.py +++ b/src/argaze/DataFeatures.py @@ -684,6 +684,40 @@ class TimestampedImages(TimestampedObjectsList): TimestampedObjectsList.__init__(self, TimestampedImage, images) +def PipelineStepExecutionTime(method): + """Define a decorator use to assess pipeline step execution time and frequency.""" + + logging.debug("@PipelineStepExecutionTime: assessing %s method execution time and frequency", method.__name__) + + def wrapper(self, *args, **kwargs): + + start = time.perf_counter() + + result = method(self, *args, **kwargs) + + end = time.perf_counter() + + # Check earlier call dates to calculate frequency + try: + + last_start, last_end = self._execution_times[method.__name__] + + if start > last_start: + + self._execution_frequencies[method.__name__] = 1 / (start - last_start) + + except KeyError: + + self._execution_frequencies[method.__name__] = math.nan + + # Store start end end dates + self._execution_times[method.__name__] = (start, end) + + return result + + return wrapper + + def PipelineStepInit(method): """Define a decorator use into PipelineStepObject class to wrap pipeline step __init__ method.""" @@ -819,6 +853,65 @@ def PipelineStepAttributeSetter(method): return wrapper +def PipelineStepMethod(method): + """Define a decorator use into PipelineStepObject class to declare pipeline method.""" + + def wrapper(self, *args, timestamp: int | float = None, unwrap: bool = False, **kwargs): + """Wrap pipeline step method to notify observers and timestamped exceptions. + + Parameters: + self: + args: any arguments defined by PipelineStepMethod. + timestamp: optional method call timestamp (unit doesn't matter) if first args parameter is not a TimestampedObject instance. + unwrap: extra arguments used in wrapper function to call wrapped method directly. + """ + if timestamp is None and len(args) > 0: + + try: + + timestamp = args[0].timestamp + + except: + + logging.error('%s.%s: %s is not a timestamped class. Use @DataFeatures.timestamp decorator.', get_class_path(self), method.__name__, type(args[0]).__name__) + + if unwrap: + + return method(self, *args, **kwargs) + + # Initialize execution outputs + exception = None + result = None + + if not self._catch_exceptions: + + # Execute wrapped method without catching exceptions + result = method(self, *args, **kwargs) + + else: + + try: + + # Execute wrapped method + result = method(self, *args, **kwargs) + + except Exception as e: + + exception = e + + # Notify observers watching 'on_' signal + self.send_signal(method.__name__, timestamp=timestamp, exception=exception) + + # Raise timestamped exception + if exception is not None: + + raise TimestampedException(exception, timestamp=timestamp) + + return result + + return wrapper + + def PipelineStepImage(method): """Define a decorator use into PipelineStepObject class to wrap pipeline step image method.""" @@ -886,7 +979,6 @@ class PipelineStepObject(): self.__initialized = True self.__name = None self.__observers = [] - self.__execution_times = {} self.__image_parameters = {} # Init protected attributes @@ -897,6 +989,11 @@ class PipelineStepObject(): # Parent attribute will be setup later by parent itself self.__parent = None + # Init execution assessment + self._execution_times = {} + self._execution_frequencies = {} + self.__last_execution_assessment_time = None + def __enter__(self): """Define default method to enter into pipeline step object context.""" @@ -975,11 +1072,6 @@ class PipelineStepObject(): observer.parent = self @property - def execution_times(self): - """Get pipeline step object observers execution times dictionary.""" - return self.__execution_times - - @property def catch_exceptions(self) -> bool: """Catch pipeline step method exception instead of crashing execution.""" return self._catch_exceptions @@ -1207,72 +1299,29 @@ class PipelineStepObject(): # Call subscription subscription(timestamp, self, exception) -def PipelineStepMethod(method): - """Define a decorator use into PipelineStepObject class to declare pipeline method. - - !!! danger - PipelineStepMethod must have a timestamp as first argument. - """ - - def wrapper(self, *args, timestamp: int | float = None, unwrap: bool = False, **kwargs): - """Wrap pipeline step method to measure execution time. - - Parameters: - self: - args: any arguments defined by PipelineStepMethod. - timestamp: optional method call timestamp (unit doesn't matter) if first args parameter is not a TimestampedObject instance. - unwrap: extra arguments used in wrapper function to call wrapped method directly. - """ - if timestamp is None and len(args) > 0: - - try: - - timestamp = args[0].timestamp - - except: - - logging.error('%s.%s: %s is not a timestamped class. Use @DataFeatures.timestamp decorator.', get_class_path(self), method.__name__, type(args[0]).__name__) - - if unwrap: - return method(self, *args, **kwargs) - - # Initialize execution time assessment - start = time.perf_counter() - exception = None - result = None - - if not self._catch_exceptions: - - # Execute wrapped method without catching exceptions - result = method(self, *args, **kwargs) - - # Measure execution time - self.execution_times[method.__name__] = (time.perf_counter() - start) * 1e3 - - else: - - try: - - # Execute wrapped method - result = method(self, *args, **kwargs) + def execution_info(self, method_name: str) -> tuple[float, float]: + """Get pipeline step method execution time (s) and frequency (Hz).""" + + time = math.nan + frequency = math.nan - except Exception as e: + # Check execution time + try: - exception = e + start, end = self._execution_times[method_name] + time = end - start - finally: + except KeyError: - # Measure execution time - self.execution_times[method.__name__] = (time.perf_counter() - start) * 1e3 + time = math.nan - # Notify observers watching 'on_' signal - self.send_signal(method.__name__, timestamp=timestamp, exception=exception) + # Check execution frequency + try: - # Raise timestamped exception - if exception is not None: + frequency = self._execution_frequencies[method_name] - raise TimestampedException(exception, timestamp=timestamp) + except KeyError: - return result + frequency = math.nan - return wrapper + return time, frequency -- cgit v1.1