Merge pull request #145 from adf-python/feature/log-resume-time

Add logging for submodule and action restart times

Author: shima004

src/adf_core_python/core/component/module/abstract_module.py

@@ -59,7 +59,11 @@ def precompute(self, precompute_data: PrecomputeData) -> AbstractModule:
   def resume(self, precompute_data: PrecomputeData) -> AbstractModule:
     self._count_resume += 1
     for sub_module in self._sub_modules:
+      start_time = time.time()
       sub_module.resume(precompute_data)
+      self._logger.debug(
+        f"{self.__class__.__name__}'s sub_module {sub_module.__class__.__name__} resume time: {time.time() - start_time:.3f}",
+      )
     return self
 
   def prepare(self) -> AbstractModule:

src/adf_core_python/core/component/tactics/tactics_agent.py

@@ -124,9 +124,17 @@ def module_precompute(self, precompute_data: PrecomputeData) -> None:
 
   def module_resume(self, precompute_data: PrecomputeData) -> None:
     for module in self._modules:
+      start_time = time.time()
       module.resume(precompute_data)
+      self._logger.debug(
+        f"module {module.__class__.__name__} resume time: {time.time() - start_time:.3f}",
+      )
     for action in self._actions:
+      start_time = time.time()
       action.resume(precompute_data)
+      self._logger.debug(
+        f"action {action.__class__.__name__} resume time: {time.time() - start_time:.3f}",
+      )
     for executor in self._command_executor:
       executor.resume(precompute_data)