Moving time assessment into a decorator.

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_<this method name>' 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_<this method name>' 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