Fix/extend runtime logging (#2005)

* fix indentation for INFO level messages

* add logging for SBML loading

* fixup

python/sdist/amici/logging.py

@@ -188,15 +188,18 @@ def wrapper_timer(*args, **kwargs):
 
             recursion = ''
             level = logging.INFO
+            level_length = len('INFO')
             if recursion_level > 1:
                 recursion = '+' * (recursion_level - 1)
                 level = logging.DEBUG
+                level_length = len('DEBUG')
+
 
             tstart = time.perf_counter()
             rval = func(*args, **kwargs)
             tend = time.perf_counter()
-            spacers = ' ' * max(54 - len(description) - len(logger.name) -
-                                len(recursion), 0)
+            spacers = ' ' * max(59 - len(description) - len(logger.name) -
+                                len(recursion) - level_length, 0)
             logger.log(
                 level, f'Finished {description}{spacers}{recursion} ({(tend - tstart):.2E}s)'
             )

python/sdist/amici/sbml_import.py

@@ -174,25 +174,32 @@ def __init__(self,
             sbml.L3P_MODULO_IS_PIECEWISE
         )
 
+    @log_execution_time('loading SBML', logger)
     def _process_document(self) -> None:
         """
         Validate and simplify document.
         """
         # Ensure we got a valid SBML model, otherwise further processing
         # might lead to undefined results
-        self.sbml_doc.validateSBML()
+        log_execution_time(f'validating SBML', logger)(
+            self.sbml_doc.validateSBML
+        )()
         _check_lib_sbml_errors(self.sbml_doc, self.show_sbml_warnings)
 
         # apply several model simplifications that make our life substantially
         # easier
         if self.sbml_doc.getModel().getNumFunctionDefinitions():
             convert_config = sbml.SBMLFunctionDefinitionConverter()\
                 .getDefaultProperties()
-            self.sbml_doc.convert(convert_config)
+            log_execution_time(f'converting SBML functions', logger)(
+                self.sbml_doc.convert
+            )(convert_config)
 
         convert_config = sbml.SBMLLocalParameterConverter().\
             getDefaultProperties()
-        self.sbml_doc.convert(convert_config)
+        dec_fun = log_execution_time(f'converting SBML local parameters', logger)(
+            self.sbml_doc.convert
+        )(convert_config)
 
         # If any of the above calls produces an error, this will be added to
         # the SBMLError log in the sbml document. Thus, it is sufficient to