From 9ab4ece9f0fedc59de76f6e6e9c5f6d7a184bda1 Mon Sep 17 00:00:00 2001 From: Ian Sullivan Date: Mon, 13 Jan 2025 16:59:56 -0800 Subject: [PATCH] Add timing log messages --- python/lsst/ap/association/testApdb.py | 18 +++++++++++++++--- 1 file changed, 15 insertions(+), 3 deletions(-) diff --git a/python/lsst/ap/association/testApdb.py b/python/lsst/ap/association/testApdb.py index ab7e94f7..2758dfc3 100644 --- a/python/lsst/ap/association/testApdb.py +++ b/python/lsst/ap/association/testApdb.py @@ -30,6 +30,7 @@ import numpy as np import pandas as pd +import time from lsst.daf.base import DateTime import lsst.dax.apdb as daxApdb @@ -210,6 +211,7 @@ def run(self, visit, detector, idGeneratorForced : `lsst.meas.base,IdGenerator`, optional ID generator for forced sources at existing diaObject locations. """ + t_sim0 = time.time() idGen = idGenerator.make_table_id_factory() idGenFakes = idGeneratorFakes.make_table_id_factory() idGenForced = idGeneratorForced.make_table_id_factory() @@ -252,11 +254,16 @@ def run(self, visit, detector, diaSourcesRaw = pd.concat([diaSourcesReal, diaSourcesBogus]) diaSources = convertTableToSdmSchema(self.schema, diaSourcesRaw, tableName="DiaSource") + t_sim1 = time.time() + self.log.info("Simulated source timing: %.2fs", t_sim1 - t_sim0) + t_load0 = time.time() diaObjects = self.loadDiaObjects(region.getBoundingCircle(), self.schema) + t_load1 = time.time() + self.log.info("diaObject load timing: %.2fs", t_load1 - t_load0) if diaObjects.empty: - self.log.info(f"diaObjects contain 0 diaSources (empty)") + self.log.info("diaObjects contain 0 diaSources (empty)") else: nDiaSources = diaObjects.nDiaSources self.log.info(f"diaObjects contain {np.min(nDiaSources)} to {np.max(nDiaSources)} diaSources") @@ -274,18 +281,21 @@ def run(self, visit, detector, nSrc = len(associatedDiaSources) dateTime = DateTime.now().toAstropy() ind = 0 + t_write0 = time.time() # Note that nObj must always be equal to or greater than nSrc for start in range(0, nObj, self.config.maximum_table_length): end = min(start + self.config.maximum_table_length, nObj) diaObjectsChunk = mergedDiaObjects.iloc[start:end] - self.log.info(f"Writing diaObject chunk {ind} of length {len(diaObjectsChunk)} to the APDB") + nObjChunk = len(diaObjectsChunk) + self.log.info(f"Writing diaObject chunk {ind} of length {nObjChunk} (of {nObj}) to the APDB") srcEnd = min(start + self.config.maximum_table_length, nSrc) if srcEnd <= start: finalDiaSources = None else: diaSourcesChunk = associatedDiaSources.iloc[start:srcEnd] finalDiaSources = convertTableToSdmSchema(self.schema, diaSourcesChunk, tableName="DiaSource") - self.log.info(f"Writing diaSource chunk {ind} of length {len(diaSourcesChunk)} to the APDB") + nSrcChunk = len(diaSourcesChunk) + self.log.info(f"Writing diaSource chunk {ind} of length {nSrcChunk} (of {nSrc}) to the APDB") diaForcedSources = self.runForcedMeasurement(diaObjectsChunk, idGenForced, visit, detector) finalDiaObjects = convertTableToSdmSchema(self.schema, diaObjectsChunk, tableName="DiaObject") @@ -295,6 +305,8 @@ def run(self, visit, detector, f" {len(finalDiaForcedSources)} to the APDB") self.writeToApdb(finalDiaObjects, finalDiaSources, finalDiaForcedSources, dateTime) ind += 1 + t_write1 = time.time() + self.log.info("APDB write timing: %.2fs", t_write1 - t_write0) marker = pexConfig.Config() return pipeBase.Struct(apdbTestMarker=marker)