DM-53756: Add new logging into zernike estimation routines.

doc/news/DM-53756.doc.md

@@ -0,0 +1 @@
+Add additional logging statements in routines related to Zernike estimation.

python/lsst/ts/wep/estimation/danish.py

@@ -21,6 +21,7 @@
 
 __all__ = ["DanishAlgorithm"]
 
+import logging
 import warnings
 
 import danish
@@ -65,6 +66,7 @@ def __init__(
         self.binning = binning
         self.lstsqKwargs = lstsqKwargs if lstsqKwargs is not None else {}
         self.jointFitPair = jointFitPair
+        self.log = logging.getLogger(__name__)
 
     @property
     def requiresPairs(self) -> bool:
@@ -424,6 +426,7 @@ def _estimatePairZk(
         )
 
         # Create model
+        self.log.info("Creating multi-donut model with danish.")
         model = danish.MultiDonutModel(
             factory,
             z_refs=zkRefs,
@@ -443,6 +446,7 @@ def _estimatePairZk(
         bounds[4] = [0.1, 5.0]
         bounds = [list(b) for b in zip(*bounds)]
 
+        self.log.info("Starting least squares optimization.")
         # Use scipy to optimize the parameters
         try:
             result = least_squares(

python/lsst/ts/wep/task/calcZernikesTask.py

@@ -575,6 +575,7 @@ def run(
         self.stampsIntra = selectedIntraStamps
 
         # Set the intrinsic map interpolators
+        self.log.info("Creating intrinsic map.")
         if self.stampsExtra[0].detector_name == self.stampsIntra[0].detector_name:
             # If both intra and extra focal donuts are from the same detector,
             # then we only have one intrinsic table to use for both.
@@ -585,6 +586,7 @@ def run(
             self.intrinsicMapIntra = self._createIntrinsicMap(intrinsicTables[1])
 
         # Estimate Zernikes from the collection of selected stamps
+        self.log.info("Starting Zernike Estimation")
         zkCoeffRaw = self.estimateZernikes.run(self.stampsExtra, self.stampsIntra, numCores=numCores)
 
         # Save the outputs in the table

python/lsst/ts/wep/task/estimateZernikesBase.py

@@ -23,6 +23,7 @@
 
 import abc
 import itertools
+import logging
 import multiprocessing as mp
 from typing import Any, Callable, Iterable
 
@@ -42,14 +43,34 @@
 def estimate_zk_pair(args: tuple[DonutStamps, DonutStamps, WfEstimator]) -> tuple[np.array, dict, dict]:
     """Estimate Zernike coefficients for a pair of donuts."""
     donutExtra, donutIntra, wfEstimator = args
+    log = logging.getLogger(__name__)
+    log.info(
+        "Calculating Zernikes for Extra Donut %s, Intra Donut %s", *(donutExtra.donut_id, donutIntra.donut_id)
+    )
     zk, zkMeta = wfEstimator.estimateZk(donutExtra.wep_im, donutIntra.wep_im)
+    log.info(
+        "Zernike estimation completed for Extra Donut %s, Intra Donut %s",
+        *(donutExtra.donut_id, donutIntra.donut_id),
+    )
+    # Log number of function evaluations if available (currently only danish)
+    if "lstsq_nfev" in zkMeta:
+        log.info(
+            "Num Iterations for Donut Pair (%s, %s): nfev = %i",
+            *(donutExtra.donut_id, donutIntra.donut_id, zkMeta["lstsq_nfev"]),
+        )
     return zk, zkMeta, wfEstimator.history
 
 
 def estimate_zk_single(args: tuple[DonutStamps, WfEstimator]) -> tuple[np.array, dict, dict]:
     """Estimate Zernike coefficients for a single donut."""
     donut, wfEstimator = args
+    log = logging.getLogger(__name__)
+    log.info("Calculating Zernikes for Donut %s", donut.donut_id)
     zk, zkMeta = wfEstimator.estimateZk(donut.wep_im)
+    log.info("Zernike estimation completed for Donut %s", donut.donut_id)
+    # Log number of function evaluations if available (currently only danish)
+    if "lstsq_nfev" in zkMeta:
+        log.info("Num Iterations for Donut %s: nfev = %i", *(donut.donut_id, zkMeta["lstsq_nfev"]))
     return zk, zkMeta, wfEstimator.history
 
 
@@ -175,6 +196,7 @@ def estimateFromPairs(
             method selected and contains a list of values,
             one for each pair of donuts.
         """
+        self.log.info("Estimating paired Zernikes.")
         # Loop over pairs in a multiprocessing pool
         args = [
             (donutExtra, donutIntra, wfEstimator)
@@ -230,6 +252,7 @@ def estimateFromIndivStamps(
             method selected and contains a list of values,
             one for each donut.
         """
+        self.log.info("Estimating single sided Zernikes.")
         # Loop over individual donut stamps with a process pool
         args = [(donut, wfEstimator) for donut in itertools.chain(donutStampsExtra, donutStampsIntra)]
         results = self._applyToList(estimate_zk_single, args, numCores)