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.
     """
+    setup_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,15 @@ def cluster_estimation_worker(
     # Get Pylance to stop complaining
     assert estimator is not None
 
+    setup_end_time = time.time()
+
+    local_logger.info(
+        f"{time.time()}: Worker setup took {setup_end_time - setup_start_time} seconds."
+    )
+
     while not controller.is_exit_requested():
+        iteration_start_time = time.time()
+
         controller.check_pause()
 
         input_data = input_queue.queue.get()
@@ -99,3 +110,9 @@ def cluster_estimation_worker(
             continue
 
         output_queue.queue.put(value)
+
+        iteration_end_time = time.time()
+
+        local_logger.info(
+            f"{time.time()}: Worker iteration took {iteration_end_time - iteration_start_time} seconds."
+        )

modules/communications/communications_worker.py

@@ -30,6 +30,7 @@ def communications_worker(
     input_queue and output_queue are data queues.
     controller is how the main process communicates to this worker process.
     """
+    setup_start_time = time.time()
 
     worker_name = pathlib.Path(__file__).stem
     process_id = os.getpid()
@@ -60,7 +61,15 @@ def communications_worker(
     # Get Pylance to stop complaining
     assert comm is not None
 
+    setup_end_time = time.time()
+
+    local_logger.info(
+        f"{time.time()}: Worker setup took {setup_end_time - setup_start_time} seconds."
+    )
+
     while not controller.is_exit_requested():
+        iteration_start_time = time.time()
+
         controller.check_pause()
 
         input_data = input_queue.queue.get()
@@ -95,3 +104,9 @@ def communications_worker(
 
             output_queue.queue.put(message)
             message_output_queue.queue.put(message)
+
+        iteration_end_time = time.time()
+
+        local_logger.info(
+            f"{time.time()}: Worker iteration took {iteration_end_time - iteration_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.
     """
+    setup_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,15 @@ def data_merge_worker(
         local_logger.error("Queue timed out on startup", True)
         return
 
+    setup_end_time = time.time()
+
+    local_logger.info(
+        f"{time.time()}: Worker setup took {setup_end_time - setup_start_time} seconds."
+    )
+
     while not controller.is_exit_requested():
+        iteration_start_time = time.time()
+
         controller.check_pause()
 
         detections: detections_and_time.DetectionsAndTime = detections_input_queue.queue.get()
@@ -107,3 +118,9 @@ def data_merge_worker(
         assert merged is not None
 
         output_queue.queue.put(merged)
+
+        iteration_end_time = time.time()
+
+        local_logger.info(
+            f"{time.time()}: Worker iteration took {iteration_end_time - iteration_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.
     """
+    setup_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,22 @@ 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
 
+    setup_end_time = time.time()
+
+    local_logger.info(
+        f"{time.time()}: Worker setup took {setup_end_time - setup_start_time} seconds."
+    )
+
     while not controller.is_exit_requested():
+        iteration_start_time = time.time()
+
         controller.check_pause()
 
         input_data = input_queue.queue.get()
@@ -78,3 +88,9 @@ def detect_target_worker(
             continue
 
         output_queue.queue.put(value)
+
+        iteration_end_time = time.time()
+
+        local_logger.info(
+            f"{time.time()}: Worker iteration took {iteration_end_time - iteration_start_time} seconds."
+        )

modules/flight_interface/flight_interface_worker.py

@@ -33,6 +33,7 @@ def flight_interface_worker(
     controller is how the main process communicates to this worker process.
     """
     # TODO: Error handling
+    setup_start_time = time.time()
 
     worker_name = pathlib.Path(__file__).stem
     process_id = os.getpid()
@@ -59,7 +60,15 @@ def flight_interface_worker(
     home_position = interface.get_home_position()
     communications_output_queue.queue.put(home_position)
 
+    setup_end_time = time.time()
+
+    local_logger.info(
+        f"{time.time()}: Worker setup took {setup_end_time - setup_start_time} seconds."
+    )
+
     while not controller.is_exit_requested():
+        iteration_start_time = time.time()
+
         controller.check_pause()
 
         time.sleep(period)
@@ -80,3 +89,9 @@ def flight_interface_worker(
             command = input_queue.queue.get()
             # Pass the decision command to the flight controller
             interface.apply_decision(command)
+
+        iteration_end_time = time.time()
+
+        local_logger.info(
+            f"{time.time()}: Worker iteration took {iteration_end_time - iteration_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
+    setup_start_time = time.time()
 
     worker_name = pathlib.Path(__file__).stem
     process_id = os.getpid()
@@ -51,7 +53,15 @@ def geolocation_worker(
     # Get Pylance to stop complaining
     assert locator is not None
 
+    setup_end_time = time.time()
+
+    local_logger.info(
+        f"{time.time()}: Worker setup took {setup_end_time - setup_start_time} seconds."
+    )
+
     while not controller.is_exit_requested():
+        iteration_start_time = time.time()
+
         controller.check_pause()
 
         input_data = input_queue.queue.get()
@@ -68,3 +78,9 @@ def geolocation_worker(
             continue
 
         output_queue.queue.put(value)
+
+        iteration_end_time = time.time()
+
+        local_logger.info(
+            f"{time.time()}: Worker iteration took {iteration_end_time - iteration_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.
     """
+    setup_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,15 @@ def video_input_worker(
     # Get Pylance to stop complaining
     assert input_device is not None
 
+    setup_end_time = time.time()
+
+    local_logger.info(
+        f"{time.time()}: Worker setup took {setup_end_time - setup_start_time} seconds."
+    )
+
     while not controller.is_exit_requested():
+        iteration_start_time = time.time()
+
         controller.check_pause()
 
         time.sleep(period)
@@ -63,3 +73,9 @@ def video_input_worker(
             continue
 
         output_queue.queue.put(value)
+
+        iteration_end_time = time.time()
+
+        local_logger.info(
+            f"{time.time()}: Worker iteration took {iteration_end_time - iteration_start_time} seconds."
+        )