Merge pull request #2905 from K4rishma/acquisition_timer

[fix][METEOR-553] Make the time estimation for overview map correct

src/odemis/acq/acqmng.py

@@ -268,7 +268,8 @@ def estimateZStackAcquisitionTime(streams, zlevels):
     acq_time = 0
     for s in streams:
         if s in zlevels.keys():
-            acq_time += s.estimateAcquisitionTime() * len(zlevels[s])
+            zs = zlevels.get(s, [0])
+            acq_time += s.estimateAcquisitionTime() * len(zs)
         else:
             acq_time += s.estimateAcquisitionTime()
     for s in streams:

src/odemis/acq/align/autofocus.py

@@ -27,6 +27,8 @@
 from typing import Tuple, Optional, List
 
 import numpy
+from odemis.util.driver import estimateMoveDuration, guessActuatorMoveDuration
+
 from odemis import model
 from odemis.acq.align import light
 from odemis.model import InstantaneousFuture
@@ -542,15 +544,23 @@ def estimateAcquisitionTime(detector, scanner=None):
     return et
 
 
-def estimateAutoFocusTime(detector, scanner=None, steps=MAX_STEPS_NUMBER):
+def estimateAutoFocusTime(detector, emt, focus: model.Actuator, dfbkg=None, good_focus=None, rng_focus=None, method=MTD_BINARY) -> float:
     """
-    detector (model.DigitalCamera or model.Detector): Detector on which to
-      improve the focus quality
-    scanner (None or model.Emitter): In case of a SED this is the scanner used
-    Estimates overlay procedure duration
+    Estimates autofocus procedure duration.
+    For the input parameters, see AutoFocus function docstring
+    :return: time in seconds
     """
-    # Add 0.5s per step to account for the focus movement (very roughly approximated)
-    return steps * estimateAcquisitionTime(detector, scanner) + steps * 0.5
+    # adjust to rng_focus if provided
+    rng = focus.axes["z"].range
+    if rng_focus:
+        rng = (max(rng[0], rng_focus[0]), min(rng[1], rng_focus[1]))
+    distance = rng[1] - rng[0]
+    # Optimally, the focus starts from middle to minimum, then maximum. Then it goes back to the middle.
+    # optimistic guess
+    move_time = guessActuatorMoveDuration(focus, "z", distance) + 2 * guessActuatorMoveDuration(focus, "z", distance/2)
+    # pessimistic guess
+    acquisition_time = MAX_STEPS_NUMBER * estimateAcquisitionTime(detector, emt)
+    return move_time + acquisition_time
 
 
 def Sparc2AutoFocus(align_mode, opm, streams=None, start_autofocus=True):
@@ -610,7 +620,7 @@ def Sparc2AutoFocus(align_mode, opm, streams=None, start_autofocus=True):
     # * 0.1 s to turn off the light
     if start_autofocus:
         # calculate the time needed for the AutoFocusSpectrometer procedure to be completed
-        af_time = _totalAutoFocusTime(spgr, dets)
+        af_time = _totalAutoFocusTime(spgr, focuser,  dets, selector, streams)
         autofocus_loading_times = (5, 5, af_time, 0.2, 5) # a list with the time that each action needs
     else:
         autofocus_loading_times = (5, 5)
@@ -971,7 +981,7 @@ def AutoFocus(detector, emt, focus, dfbkg=None, good_focus=None, rng_focus=None,
     # Create ProgressiveFuture and update its state to RUNNING
     est_start = time.time() + 0.1
     f = model.ProgressiveFuture(start=est_start,
-                                end=est_start + estimateAutoFocusTime(detector, emt))
+                                end=est_start + estimateAutoFocusTime(detector, emt, focus, dfbkg, good_focus, rng_focus))
     f._autofocus_state = RUNNING
     f._autofocus_lock = threading.Lock()
     f.task_canceller = _CancelAutoFocus
@@ -1019,7 +1029,7 @@ def AutoFocusSpectrometer(spectrograph, focuser, detectors, selector=None, strea
     # Create ProgressiveFuture and update its state to RUNNING
     est_start = time.time() + 0.1
     #calculate the time for the AutoFocusSpectrometer procedure to be completed
-    a_time = _totalAutoFocusTime(spectrograph, detectors)
+    a_time = _totalAutoFocusTime(spectrograph, focuser, detectors, selector, streams)
     f = model.ProgressiveFuture(start=est_start, end=est_start + a_time)
     f.task_canceller = _CancelAutoFocusSpectrometer
     # Extra info for the canceller
@@ -1036,10 +1046,10 @@ def AutoFocusSpectrometer(spectrograph, focuser, detectors, selector=None, strea
 MOVE_TIME_DETECTOR = 5  # , for the detector selector
 
 
-def _totalAutoFocusTime(spgr, dets):
-    ngs = len(spgr.axes["grating"].choices)
-    nds = len(dets)
-    et = estimateAutoFocusTime(dets[0], None)
+def _totalAutoFocusTime(spectrograph, focuser, detectors, selector, streams):
+    ngs = len(spectrograph.axes["grating"].choices)
+    nds = len(detectors)
+    et = estimateAutoFocusTime(detectors[0], None, focuser)
 
     # 1 time for each grating/detector combination, with the gratings changing slowly
     move_et = ngs * MOVE_TIME_GRATING if ngs > 1 else 0

src/odemis/acq/align/roi_autofocus.py

@@ -21,12 +21,11 @@
 """
 
 import logging
+import statistics
 import threading
 import time
 from concurrent.futures._base import CANCELLED, FINISHED, RUNNING, CancelledError
-from typing import Iterable
-
-import numpy
+from typing import Iterable, Dict, List, Optional
 
 from odemis import model
 from odemis.acq import align
@@ -59,20 +58,34 @@ def do_autofocus_in_roi(
     :return: (list) list of focus positions in x, y, z
     """
     focus_positions = []
+    average_focus_time = None
     try:
         init_pos = stage.position.value
+        time_per_action = {"focus": [], "move": []}
+        start_time = time.time()
+        for i, (x, y) in enumerate(focus_points):
+
+            # Calculate the average focus time for the previous focus positions
+            if i > 0:
+                average_focus_time = (time.time() - start_time) / i
 
-        for (x, y) in focus_points:
+            # Update the time progress
+            f.set_progress(end=estimate_autofocus_in_roi_time(len(focus_points) - i, ccd, focus, focus_range,
+                                                              average_focus_time) + time.time())
             with f._autofocus_roi_lock:
                 if f._autofocus_roi_state == CANCELLED:
                     raise CancelledError()
 
                 logging.debug(f"Moving the stage to autofocus at position: {x, y}")
+                move_to_pos_start = time.time()
                 stage.moveAbsSync({"x": x, "y": y})
+                time_per_action["move"].append(time.time() - move_to_pos_start)
                 # run autofocus
+                focus_start = time.time()
                 f._running_subf = align.AutoFocus(ccd, None, focus, rng_focus=focus_range)
 
             foc_pos, foc_lev, conf = f._running_subf.result(timeout=900)
+            time_per_action["focus"].append(time.time() - focus_start)
             if conf >= conf_level:
                 focus_positions.append([stage.position.value["x"],
                                         stage.position.value["y"],
@@ -91,6 +104,10 @@ def do_autofocus_in_roi(
         raise
 
     finally:
+        avg_per_action = {key: statistics.mean(val) for key, val in time_per_action.items() if len(val) > 0}
+        logging.debug(f"The actual time taken per focus position for each action is {time_per_action}")
+        logging.debug(f"The average time taken per focus position for each action is {avg_per_action}")
+        logging.debug(f"The average time taken per focus position is {average_focus_time}")
         logging.debug(f"Moving back to initial stage position {init_pos}")
         stage.moveAbsSync(init_pos)
         with f._autofocus_roi_lock:
@@ -101,15 +118,26 @@ def do_autofocus_in_roi(
     return focus_positions
 
 
-def estimate_autofocus_in_roi_time(n_focus_points, detector):
+def estimate_autofocus_in_roi_time(n_focus_points, detector, focus, focus_rng, average_focus_time=None):
     """
     Estimate the time it will take to run autofocus in a roi with nx * ny positions.
     :param n_focus_points: (tuple) number of focus points in x and y direction
     :param detector: component of the detector
-    :return:
+    :param focus: focus component
+    :param focus_range: focus range, tuple of (zmin, zmax) in meters
+    :param average_focus_time:average time taken to run autofocus and move stage for one focus position
+    :return: time in seconds to complete autofocus procedure at given focus points
     """
-    # add 10 seconds to account for stage movement between focus points
-    return n_focus_points * (estimateAutoFocusTime(detector, None) + 10)
+    # After the autofocus on first focus point, update the time taken for subsequent focus positions
+    if average_focus_time:
+        return average_focus_time * n_focus_points
+    focus_time = n_focus_points * estimateAutoFocusTime(detector, None, focus, rng_focus=focus_rng)
+    # 10 seconds to account for stage movement between focus points
+    move_time = n_focus_points * 10
+    logging.info(
+        f"The computed time in seconds for autofocus for {n_focus_points} focus positions for move is {move_time}, "
+        f"focus is {focus_time}")
+    return focus_time + move_time
 
 
 def _cancel_autofocus_bbox(future):
@@ -154,7 +182,7 @@ def autofocus_in_roi(
     n_focus_points = len(focus_points)
     f = model.ProgressiveFuture(start=est_start,
                                 end=est_start + estimate_autofocus_in_roi_time(n_focus_points,
-                                                                               ccd))
+                                                                               ccd, focus, focus_range))
     f._autofocus_roi_state = RUNNING
     f._autofocus_roi_lock = threading.Lock()
     f.task_canceller = _cancel_autofocus_bbox

src/odemis/acq/align/spot.py

@@ -288,7 +288,7 @@ def estimateAlignmentTime(et, dist=None, n_autofocus=2):
     n_autofocus (int): number of autofocus procedures
     returns (float):  process estimated time #s
     """
-    return estimateCenterTime(et, dist) + n_autofocus * autofocus.estimateAutoFocusTime(et)  # s
+    return estimateCenterTime(et, dist) + n_autofocus * (autofocus.MAX_STEPS_NUMBER / 2) * et  # s
 
 
 def _set_blanker(escan, active):

src/odemis/acq/align/test/roi_autofocus_test.py

@@ -142,6 +142,6 @@ def test_estimate_autofocus_in_roi(self):
         Tests time estimation of autofocus in roi
         """
         n_focus_points = 9
-        min_time = n_focus_points * estimateAutoFocusTime(self.ccd, None)
-        estimated_time = estimate_autofocus_in_roi_time(n_focus_points, self.ccd)
+        min_time = n_focus_points * estimateAutoFocusTime(self.ccd, None, self.focus, rng_focus=self.focus_range)
+        estimated_time = estimate_autofocus_in_roi_time(n_focus_points, self.ccd, self.focus, self.focus_range)
         self.assertGreaterEqual(estimated_time, min_time)

src/odemis/acq/feature.py

@@ -399,7 +399,12 @@ def estimate_acquisition_time(self) -> float:
 
         autofocus_time = 0
         if self.use_autofocus:
-            autofocus_time = estimateAutoFocusTime(self.streams[0].detector, None, steps=20)
+            rel_rng = SAFE_REL_RANGE_DEFAULT
+            focus_rng = (self.focus.position.value["z"] + rel_rng[0], self.focus.position.value["z"] + rel_rng[1])
+            autofocus_time = estimateAutoFocusTime(detector=self.streams[0].detector,
+                                                        emt=None,
+                                                        focus=self.focus,
+                                                        rng_focus=focus_rng)
 
         if self.zparams:
             zlevels = self._generate_zlevels(zmin=self.zparams["zmin"],