Add logging to reading of parameters and responses

src/ert/_c_wrappers/enkf/config/surface_config.py

@@ -1,7 +1,5 @@
 from __future__ import annotations
 
-import logging
-import time
 from dataclasses import dataclass
 from pathlib import Path
 from typing import TYPE_CHECKING
@@ -14,8 +12,6 @@
 if TYPE_CHECKING:
     from ert.storage import EnsembleAccessor, EnsembleReader
 
-_logger = logging.getLogger(__name__)
-
 
 @dataclass
 class SurfaceConfig(ParameterConfig):
@@ -32,7 +28,6 @@ class SurfaceConfig(ParameterConfig):
     base_surface_path: str
 
     def load(self, run_path: Path, real_nr: int, ensemble: EnsembleAccessor):
-        t = time.perf_counter()
         file_name = self.forward_init_file
         if "%d" in file_name:
             file_name = file_name % real_nr
@@ -52,10 +47,8 @@ def load(self, run_path: Path, real_nr: int, ensemble: EnsembleAccessor):
         )
 
         ensemble.save_parameters(self.name, real_nr, da)
-        _logger.debug(f"load() time_used {(time.perf_counter() - t):.4f}s")
 
     def save(self, run_path: Path, real_nr: int, ensemble: EnsembleReader):
-        t = time.perf_counter()
         data = ensemble.load_parameters(self.name, real_nr)
 
         surf = xtgeo.RegularSurface(
@@ -73,4 +66,3 @@ def save(self, run_path: Path, real_nr: int, ensemble: EnsembleReader):
         file_path = run_path / self.output_file
         file_path.parent.mkdir(exist_ok=True, parents=True)
         surf.to_file(file_path, fformat="irap_ascii")
-        _logger.debug(f"save() time_used {(time.perf_counter() - t):.4f}s")

src/ert/callbacks.py

@@ -1,6 +1,7 @@
 from __future__ import annotations
 
 import logging
+import time
 from pathlib import Path
 from typing import Callable, List, Tuple
 
@@ -25,9 +26,15 @@ def _read_parameters(
         if not config_node.forward_init:
             continue
         try:
+            start_time = time.perf_counter()
+            logger.info(f"Starting to load parameter: {config_node.name}")
             config_node.load(
                 Path(run_arg.runpath), run_arg.iens, run_arg.ensemble_storage
             )
+            logger.info(
+                f"Saved {config_node.name} to storage",
+                extra={"Time": f"{(time.perf_counter() - start_time):.4f}s"},
+            )
         except ValueError as err:
             error_msg += str(err)
             result = LoadResult(LoadStatus.LOAD_FAILURE, error_msg)
@@ -45,8 +52,14 @@ def _write_responses_to_storage(
             if not config.keys:
                 continue
         try:
+            start_time = time.perf_counter()
+            logger.info(f"Starting to load response: {config.name}")
             ds = config.read_from_file(run_arg.runpath, run_arg.iens)
             run_arg.ensemble_storage.save_response(config.name, ds, run_arg.iens)
+            logger.info(
+                f"Saved {config.name} to storage",
+                extra={"Time": f"{(time.perf_counter() - start_time):.4f}s"},
+            )
         except ValueError as err:
             errors.append(str(err))
     if errors: