Merge pull request #184 from lsst/tickets/DM-31528

DM-31528: Add more log messages to the measure task

python/lsst/meas/base/forcedMeasurement.py

@@ -56,6 +56,7 @@
 
 import lsst.pex.config
 import lsst.pipe.base
+import time
 
 from .pluginRegistry import PluginRegistry
 from .baseMeasurement import (BaseMeasurementPluginConfig, BaseMeasurementPlugin,
@@ -190,18 +191,21 @@ class ForcedMeasurementConfig(BaseMeasurementConfig):
         default=[],
         doc="Plugins to run on undeblended image"
     )
-
     copyColumns = lsst.pex.config.DictField(
         keytype=str, itemtype=str, doc="Mapping of reference columns to source columns",
         default={"id": "objectId", "parent": "parentObjectId", "deblend_nChild": "deblend_nChild",
                  "coord_ra": "coord_ra", "coord_dec": "coord_dec"}
     )
-
     checkUnitsParseStrict = lsst.pex.config.Field(
         doc="Strictness of Astropy unit compatibility check, can be 'raise', 'warn' or 'silent'",
         dtype=str,
         default="raise",
     )
+    loggingInterval = lsst.pex.config.Field(
+        dtype=int,
+        default=600,
+        doc="Interval (in seconds) to log messages (at VERBOSE level) while running measurement plugins."
+    )
 
     def setDefaults(self):
         self.slots.centroid = "base_TransformedCentroid"
@@ -336,6 +340,7 @@ def run(self, measCat, exposure, refCat, refWcs, exposureId=None, beginOrder=Non
 
         self.log.info("Performing forced measurement on %d source%s", len(refCat),
                       "" if len(refCat) == 1 else "s")
+        nextLogTime = time.time() + self.config.loggingInterval
 
         if self.config.doReplaceWithNoise:
             noiseReplacer = NoiseReplacer(self.config.noiseReplacer, exposure,
@@ -376,13 +381,22 @@ def run(self, measCat, exposure, refCat, refWcs, exposureId=None, beginOrder=Non
             self.callMeasureN(measChildCat, exposure, refChildCat,
                               beginOrder=beginOrder, endOrder=endOrder)
             noiseReplacer.removeSource(refParentRecord.getId())
+            # Log a message if it has been a while since the last log.
+            if (currentTime := time.time()) > nextLogTime:
+                self.log.verbose("Forced measurement complete for %d parents (and their children) out of %d",
+                                 parentIdx + 1, len(refParentCat))
+                nextLogTime = currentTime + self.config.loggingInterval
         noiseReplacer.end()
 
         # Undeblended plugins only fire if we're running everything
         if endOrder is None:
-            for measRecord, refRecord in zip(measCat, refCat):
+            for recordIndex, (measRecord, refRecord) in enumerate(zip(measCat, refCat)):
                 for plugin in self.undeblendedPlugins.iter():
                     self.doMeasurement(plugin, measRecord, exposure, refRecord, refWcs)
+                if (currentTime := time.time()) > nextLogTime:
+                    self.log.verbose("Undeblended forced measurement complete for %d sources out of %d",
+                                     recordIndex + 1, len(refCat))
+                    nextLogTime = currentTime + self.config.loggingInterval
 
     def generateMeasCat(self, exposure, refCat, refWcs, idFactory=None):
         r"""Initialize an output catalog from the reference catalog.

python/lsst/meas/base/sfm.py

@@ -32,6 +32,8 @@
 """
 
 import lsst.pipe.base as pipeBase
+import lsst.pex.config
+import time
 
 from .pluginRegistry import PluginRegistry
 from .baseMeasurement import (BaseMeasurementPluginConfig, BaseMeasurementPlugin,
@@ -154,6 +156,11 @@ class SingleFrameMeasurementConfig(BaseMeasurementConfig):
         default=[],
         doc="Plugins to run on undeblended image"
     )
+    loggingInterval = lsst.pex.config.Field(
+        dtype=int,
+        default=600,
+        doc="Interval (in seconds) to log messages (at VERBOSE level) while running measurement plugins."
+    )
 
 
 class SingleFrameMeasurementTask(BaseMeasurementTask):
@@ -291,6 +298,7 @@ def runPlugins(self, noiseReplacer, measCat, exposure, beginOrder=None, endOrder
                       nMeasCat, ("" if nMeasCat == 1 else "s"),
                       nMeasParentCat, ("" if nMeasParentCat == 1 else "s"),
                       nMeasCat - nMeasParentCat, ("" if nMeasCat - nMeasParentCat == 1 else "ren"))
+        nextLogTime = time.time() + self.config.loggingInterval
 
         childrenIter = measCat.getChildren([measParentRecord.getId() for measParentRecord in measParentCat])
         for parentIdx, (measParentRecord, measChildCat) in enumerate(zip(measParentCat, childrenIter)):
@@ -319,15 +327,25 @@ def runPlugins(self, noiseReplacer, measCat, exposure, beginOrder=None, endOrder
                               beginOrder=beginOrder, endOrder=endOrder)
             self.callMeasureN(measChildCat, exposure, beginOrder=beginOrder, endOrder=endOrder)
             noiseReplacer.removeSource(measParentRecord.getId())
+            # Log a message if it has been a while since the last log.
+            if (currentTime := time.time()) > nextLogTime:
+                self.log.verbose("Measurement complete for %d parents (and their children) out of %d",
+                                 parentIdx + 1, nMeasParentCat)
+                nextLogTime = currentTime + self.config.loggingInterval
 
         # When done, restore the exposure to its original state
         noiseReplacer.end()
 
         # Undeblended plugins only fire if we're running everything
         if endOrder is None:
-            for source in measCat:
+            for sourceIndex, source in enumerate(measCat):
                 for plugin in self.undeblendedPlugins.iter():
                     self.doMeasurement(plugin, source, exposure)
+                if (currentTime := time.time()) > nextLogTime:
+                    self.log.verbose("Undeblended measurement complete for %d sources out of %d",
+                                     sourceIndex + 1, nMeasCat)
+                    nextLogTime = currentTime + self.config.loggingInterval
+
         # Now we loop over all of the sources one more time to compute the
         # blendedness metrics
         if self.doBlendedness: