Add timing logs to workers

modules/cluster_estimation/cluster_estimation_worker.py

@@ -4,6 +4,7 @@
 
 import os
 import pathlib
+import time
 
 from modules import detection_in_world
 from utilities.workers import queue_proxy_wrapper
@@ -47,6 +48,8 @@ def cluster_estimation_worker(
     worker_controller: worker_controller.WorkerController
         How the main process communicates to this worker process.
     """
+    start_time = time.time()
+
     worker_name = pathlib.Path(__file__).stem
     process_id = os.getpid()
     result, local_logger = logger.Logger.create(f"{worker_name}_{process_id}", True)
@@ -72,7 +75,13 @@ def cluster_estimation_worker(
     # Get Pylance to stop complaining
     assert estimator is not None
 
+    end_time = time.time()
+
+    local_logger.info(f"{time.time()}: Class object creation took {end_time - start_time} seconds.")
+
     while not controller.is_exit_requested():
+        start_time = time.time()
+
         controller.check_pause()
 
         input_data = input_queue.queue.get()
@@ -99,3 +108,7 @@ def cluster_estimation_worker(
             continue
 
         output_queue.queue.put(value)
+
+        end_time = time.time()
+
+        local_logger.info(f"{time.time()}: Worker iteration took {end_time - start_time} seconds.")

modules/communications/communications_worker.py

@@ -5,6 +5,7 @@
 import os
 import pathlib
 import queue
+import time
 
 from modules import object_in_world
 from . import communications
@@ -27,6 +28,7 @@ def communications_worker(
     input_queue and output_queue are data queues.
     controller is how the main process communicates to this worker process.
     """
+    start_time = time.time()
 
     worker_name = pathlib.Path(__file__).stem
     process_id = os.getpid()
@@ -57,7 +59,13 @@ def communications_worker(
     # Get Pylance to stop complaining
     assert comm is not None
 
+    end_time = time.time()
+
+    local_logger.info(f"{time.time()}: Class object creation took {end_time - start_time} seconds.")
+
     while not controller.is_exit_requested():
+        start_time = time.time()
+
         controller.check_pause()
 
         input_data = input_queue.queue.get()
@@ -84,3 +92,7 @@ def communications_worker(
             continue
 
         output_queue.queue.put(value)
+
+        end_time = time.time()
+
+        local_logger.info(f"{time.time()}: Worker iteration took {end_time - start_time} seconds.")

modules/data_merge/data_merge_worker.py

@@ -5,6 +5,7 @@
 import os
 import pathlib
 import queue
+import time
 
 from utilities.workers import queue_proxy_wrapper
 from utilities.workers import worker_controller
@@ -31,6 +32,8 @@ def data_merge_worker(
     Merge work is done in the worker process as the queues and control mechanisms
     are naturally available.
     """
+    start_time = time.time()
+
     worker_name = pathlib.Path(__file__).stem
     process_id = os.getpid()
     result, local_logger = logger.Logger.create(f"{worker_name}_{process_id}", True)
@@ -52,7 +55,13 @@ def data_merge_worker(
         local_logger.error("Queue timed out on startup", True)
         return
 
+    end_time = time.time()
+
+    local_logger.info(f"{time.time()}: Setup took {end_time - start_time} seconds.")
+
     while not controller.is_exit_requested():
+        start_time = time.time()
+
         controller.check_pause()
 
         detections: detections_and_time.DetectionsAndTime = detections_input_queue.queue.get()
@@ -107,3 +116,7 @@ def data_merge_worker(
         assert merged is not None
 
         output_queue.queue.put(merged)
+
+        end_time = time.time()
+
+        local_logger.info(f"{time.time()}: Worker iteration took {end_time - start_time} seconds.")

modules/detect_target/detect_target_worker.py

@@ -4,6 +4,7 @@
 
 import os
 import pathlib
+import time
 
 from modules import image_and_time
 from utilities.workers import queue_proxy_wrapper
@@ -34,6 +35,8 @@ def detect_target_worker(
     input_queue and output_queue are data queues.
     controller is how the main process communicates to this worker process.
     """
+    start_time = time.time()
+
     worker_name = pathlib.Path(__file__).stem
     process_id = os.getpid()
     result, local_logger = logger.Logger.create(f"{worker_name}_{process_id}", True)
@@ -53,15 +56,20 @@ def detect_target_worker(
         config,
         local_logger,
     )
-
     if not result:
         local_logger.error("Could not construct detector.")
         return
 
     # Get Pylance to stop complaining
     assert detector is not None
 
+    end_time = time.time()
+
+    local_logger.info(f"{time.time()}: Class object creation took {end_time - start_time} seconds.")
+
     while not controller.is_exit_requested():
+        start_time = time.time()
+
         controller.check_pause()
 
         input_data = input_queue.queue.get()
@@ -78,3 +86,7 @@ def detect_target_worker(
             continue
 
         output_queue.queue.put(value)
+
+        end_time = time.time()
+
+        local_logger.info(f"{time.time()}: Worker iteration took {end_time - start_time} seconds.")

modules/flight_interface/flight_interface_worker.py

@@ -31,6 +31,7 @@ def flight_interface_worker(
     controller is how the main process communicates to this worker process.
     """
     # TODO: Error handling
+    start_time = time.time()
 
     worker_name = pathlib.Path(__file__).stem
     process_id = os.getpid()
@@ -57,7 +58,13 @@ def flight_interface_worker(
     home_position = interface.get_home_position()
     communications_output_queue.queue.put(home_position)
 
+    end_time = time.time()
+
+    local_logger.info(f"{time.time()}: Class object creation took {end_time - start_time} seconds.")
+
     while not controller.is_exit_requested():
+        start_time = time.time()
+
         controller.check_pause()
 
         time.sleep(period)
@@ -73,3 +80,7 @@ def flight_interface_worker(
             command = input_queue.queue.get()
             # Pass the decision command to the flight controller
             interface.apply_decision(command)
+
+        end_time = time.time()
+
+        local_logger.info(f"{time.time()}: Worker iteration took {end_time - start_time} seconds.")

modules/geolocation/geolocation_worker.py

@@ -4,6 +4,7 @@
 
 import os
 import pathlib
+import time
 
 from modules import merged_odometry_detections
 from utilities.workers import queue_proxy_wrapper
@@ -27,6 +28,7 @@ def geolocation_worker(
     controller is how the main process communicates to this worker process.
     """
     # TODO: Handle errors better
+    start_time = time.time()
 
     worker_name = pathlib.Path(__file__).stem
     process_id = os.getpid()
@@ -51,7 +53,13 @@ def geolocation_worker(
     # Get Pylance to stop complaining
     assert locator is not None
 
+    end_time = time.time()
+
+    local_logger.info(f"{time.time()}: Class object creation took {end_time - start_time} seconds.")
+
     while not controller.is_exit_requested():
+        start_time = time.time()
+
         controller.check_pause()
 
         input_data = input_queue.queue.get()
@@ -68,3 +76,7 @@ def geolocation_worker(
             continue
 
         output_queue.queue.put(value)
+
+        end_time = time.time()
+
+        local_logger.info(f"{time.time()}: Worker iteration took {end_time - start_time} seconds.")

modules/video_input/video_input_worker.py

@@ -32,6 +32,8 @@ def video_input_worker(
     output_queue is the data queue.
     controller is how the main process communicates to this worker process.
     """
+    start_time = time.time()
+
     worker_name = pathlib.Path(__file__).stem
     process_id = os.getpid()
     result, local_logger = logger.Logger.create(f"{worker_name}_{process_id}", True)
@@ -53,7 +55,13 @@ def video_input_worker(
     # Get Pylance to stop complaining
     assert input_device is not None
 
+    end_time = time.time()
+
+    local_logger.info(f"{time.time()}: Class object creation took {end_time - start_time} seconds.")
+
     while not controller.is_exit_requested():
+        start_time = time.time()
+
         controller.check_pause()
 
         time.sleep(period)
@@ -63,3 +71,7 @@ def video_input_worker(
             continue
 
         output_queue.queue.put(value)
+
+        end_time = time.time()
+
+        local_logger.info(f"{time.time()}: Worker iteration took {end_time - start_time} seconds.")