Better log messages

Author: tanner-andrulis

hwcomponents/_logging.py

@@ -74,6 +74,8 @@ def _init_logger(self, name: str = None):
 
     @property
     def logger(self) -> logging.Logger:
+        if getattr(self.__class__, "_hwcomponents_logger", None) is not None:
+            return self.__class__._hwcomponents_logger
         if getattr(self, "_logger", None) is None:
             if hasattr(self, "__name__"):
                 self._logger = get_logger(self.__name__)

hwcomponents/_model_wrapper.py

@@ -323,10 +323,24 @@ def get_initialized_subclass(self, query: ModelQuery) -> ComponentModel:
         self.logger.info(
             f"Initializing {self.model_cls.__name__} from {self.model_cls.__module__}"
         )
-        subclass = self.init_function.call(
-            query.component_attributes, self.component_name
-        )
-        subclass._init_logger()
+        try:
+            self.model_cls._hwcomponents_logger = self.logger
+            subclass = self.init_function.call(
+                query.component_attributes, self.component_name
+            )
+        except Exception:
+            raise
+        finally:
+            self.model_cls._hwcomponents_logger = None
+
+        for message in pop_all_messages(subclass.logger):
+            self.logger.info(f"{message}")
+
+        for subcomponent in subclass.subcomponents:
+            self.logger.info(f"Log for subcomponent {subcomponent.__class__.__name__}:")
+            for message in pop_all_messages(subcomponent.logger):
+                if message:
+                    self.logger.info(f"\t{message}")
         return subclass
 
     def get_matching_actions(self, query: ModelQuery) -> List[CallableFunction]:

hwcomponents/model.py

@@ -3,7 +3,7 @@
 from numbers import Number
 from functools import wraps
 from typing import Any, Callable, List, Type, Union, TypeVar
-from hwcomponents._logging import ListLoggable
+from hwcomponents._logging import ListLoggable, pop_all_messages
 from hwcomponents._util import parse_float
 
 T = TypeVar("T", bound="ComponentModel")
@@ -52,10 +52,15 @@ def action(
 
     @wraps(func)
     def wrapper(self: "ComponentModel", *args, **kwargs):
+        self.logger.info("")
+        self.logger.info(
+            f"Calling action {self.__class__.__name__}.{func.__name__} with arguments {args} and {kwargs}"
+        )
         for subcomponent in self.subcomponents:
             subcomponent._energy_used = 0
             subcomponent._latency_used = 0
         scale = 1
+        scalestr = None
         if bits_per_action is not None and "bits_per_action" in kwargs:
             nominal_bits = None
             try:
@@ -69,6 +74,7 @@ def wrapper(self: "ComponentModel", *args, **kwargs):
                     f"are defined in the class."
                 )
             scale = kwargs["bits_per_action"] / nominal_bits
+            scalestr = f"Scaling by {kwargs['bits_per_action']=} / {nominal_bits=}"
         kwargs = {k: v for k, v in kwargs.items() if k not in additional_kwargs}
         returned_value = func(self, *args, **kwargs)
         # Normalize return to (energy, latency)
@@ -89,21 +95,48 @@ def wrapper(self: "ComponentModel", *args, **kwargs):
                 f"Expected a tuple of (energy, latency), got {returned_value}."
             )
 
+        self.logger.info(
+            f"Function {func.__name__} returned energy {energy_val} and latency {latency_val}"
+        )
+        if scalestr is not None:
+            self.logger.info(scalestr)
+
         energy_val *= self.energy_scale
+        if self.energy_scale != 1:
+            self.logger.info(f"Scaling energy by {self.energy_scale=}")
         for subcomponent in self.subcomponents:
+            self.logger.info(
+                f"Adding subcomponent {subcomponent.__class__.__name__} energy {subcomponent._energy_used}"
+            )
             energy_val += subcomponent._energy_used
             subcomponent._energy_used = 0
         energy_val *= scale
         self._energy_used += energy_val
 
         latency_val *= self.latency_scale
+        if self.latency_scale != 1:
+            self.logger.info(f"Scaling latency by {self.latency_scale=}")
         target_func = max if pipelined_subcomponents else sum
+        x = "Max" if pipelined_subcomponents else "Summ"
         for subcomponent in self.subcomponents:
+            self.logger.info(
+                f"{x}ing subcomponent {subcomponent.__class__.__name__} latency {subcomponent._latency_used}"
+            )
             latency_val = target_func((latency_val, subcomponent._latency_used))
             subcomponent._latency_used = 0
         latency_val *= scale
         self._latency_used += latency_val
 
+        for subcomponent in self.subcomponents:
+            self.logger.info(f"Log for subcomponent {subcomponent.__class__.__name__}:")
+            for message in pop_all_messages(subcomponent.logger):
+                if message:
+                    self.logger.info(f"\t{message}")
+
+        self.logger.info(
+            f"** Final return value for {self.__class__.__name__}.{func.__name__}: energy {energy_val} and latency {latency_val}"
+        )
+
         return energy_val, latency_val
 
     wrapper._is_component_action = True
@@ -544,4 +577,4 @@ def resolve_multiple_ways_to_calculate_value(
                 + "\n\t".join(f"{fname}: {value}" for fname, value in success_values)
             )
 
-        return next(iter(values))
+        return next(iter(values))

hwcomponents/select_models.py

@@ -42,6 +42,8 @@ def _call_model(
         # Add the full traceback
         import traceback
 
+        estimation.add_messages(pop_all_messages(model.logger))
+
         estimation.add_messages(traceback.format_exc().split("\n"))
         return estimation