Add a decorator that logs how long a function took / was slow.

metricflow/dataflow/builder/dataflow_plan_builder.py

@@ -60,6 +60,7 @@
 from metricflow.errors.errors import UnableToSatisfyQueryError
 from metricflow.filters.time_constraint import TimeRangeConstraint
 from metricflow.mf_logging.pretty_print import mf_pformat
+from metricflow.mf_logging.runtime import log_runtime
 from metricflow.model.semantic_manifest_lookup import SemanticManifestLookup
 from metricflow.plan_conversion.column_resolver import DunderColumnAssociationResolver
 from metricflow.plan_conversion.node_processor import PreJoinNodeProcessor
@@ -149,6 +150,7 @@ def __init__(  # noqa: D
             else node_output_resolver
         )
 
+    @log_runtime()
     def build_plan(
         self,
         query_spec: MetricFlowQuerySpec,
@@ -583,6 +585,7 @@ def _build_metrics_output_node(
 
         return CombineAggregatedOutputsNode(parent_nodes=output_nodes)
 
+    @log_runtime()
     def build_plan_for_distinct_values(self, query_spec: MetricFlowQuerySpec) -> DataflowPlan:
         """Generate a plan that would get the distinct values of a linkable instance.
 

metricflow/mf_logging/runtime.py

@@ -0,0 +1,42 @@
+from __future__ import annotations
+
+import logging
+import time
+from typing import Callable, TypeVar
+
+from typing_extensions import ParamSpec
+
+logger = logging.getLogger(__name__)
+
+ReturnType = TypeVar("ReturnType")
+ParametersType = ParamSpec("ParametersType")
+
+
+def log_runtime(
+    runtime_warning_threshold: float = 3.0,
+) -> Callable[[Callable[ParametersType, ReturnType]], Callable[ParametersType, ReturnType]]:
+    """Logs how long a function took to run.
+
+    If the runtime exceeds runtime_warning_threshold, then a warning is logged.
+    """
+
+    def decorator(wrapped_function: Callable[ParametersType, ReturnType]) -> Callable[ParametersType, ReturnType]:
+        def _inner(*args: ParametersType.args, **kwargs: ParametersType.kwargs) -> ReturnType:
+            # __qualname__ includes the path like MyClass.my_function
+            function_name = f"{wrapped_function.__qualname__}()"
+            start_time = time.time()
+            logger.info(f"Starting {function_name}")
+
+            try:
+                result = wrapped_function(*args, **kwargs)
+            finally:
+                runtime = time.time() - start_time
+                logger.info(f"Finished {function_name} in {runtime:.1f}s")
+                if runtime > runtime_warning_threshold:
+                    logger.warning(f"{function_name} is slow with a runtime of {runtime:.1f}s")
+
+            return result
+
+        return _inner
+
+    return decorator

metricflow/query/group_by_item/filter_spec_resolution/filter_spec_resolver.py

@@ -11,6 +11,7 @@
 from dbt_semantic_interfaces.protocols import WhereFilter, WhereFilterIntersection
 from typing_extensions import override
 
+from metricflow.mf_logging.runtime import log_runtime
 from metricflow.model.semantic_manifest_lookup import SemanticManifestLookup
 from metricflow.naming.object_builder_str import ObjectBuilderNameConverter
 from metricflow.query.group_by_item.candidate_push_down.push_down_visitor import DagTraversalPathTracker
@@ -70,6 +71,7 @@ def __init__(  # noqa: D
         self._manifest_lookup = manifest_lookup
         self._resolution_dag = resolution_dag
 
+    @log_runtime()
     def resolve_lookup(self) -> FilterSpecResolutionLookUp:
         """Find all where filters and return a lookup that provides the specs for the included group-by-items."""
         visitor = _ResolveWhereFilterSpecVisitor(manifest_lookup=self._manifest_lookup)

metricflow/query/query_parser.py

@@ -19,6 +19,7 @@
 from metricflow.filters.time_constraint import TimeRangeConstraint
 from metricflow.mf_logging.formatting import indent
 from metricflow.mf_logging.pretty_print import mf_pformat
+from metricflow.mf_logging.runtime import log_runtime
 from metricflow.model.semantic_manifest_lookup import SemanticManifestLookup
 from metricflow.naming.dunder_scheme import DunderNamingScheme
 from metricflow.naming.metric_scheme import MetricNamingScheme
@@ -295,6 +296,7 @@ def _raise_exception_if_there_are_errors(
 
         raise InvalidQueryException(self.generate_error_message(input_to_issue_set=input_to_issue_set))
 
+    @log_runtime()
     def parse_and_validate_query(
         self,
         metric_names: Optional[Sequence[str]] = None,

metricflow/query/query_resolver.py

@@ -8,6 +8,7 @@
 
 from metricflow.dag.dag_to_text import dag_as_text
 from metricflow.mf_logging.pretty_print import mf_pformat
+from metricflow.mf_logging.runtime import log_runtime
 from metricflow.model.semantic_manifest_lookup import SemanticManifestLookup
 from metricflow.naming.metric_scheme import MetricNamingScheme
 from metricflow.query.group_by_item.filter_spec_resolution.filter_spec_lookup import FilterSpecResolutionLookUp
@@ -319,6 +320,7 @@ def _build_filter_spec_lookup(
 
         return where_filter_spec_resolver.resolve_lookup()
 
+    @log_runtime()
     def resolve_query(self, resolver_input_for_query: ResolverInputForQuery) -> MetricFlowQueryResolution:
         """Resolve the query into specs that can be passed into the next stage in query processing."""
         metric_inputs = resolver_input_for_query.metric_inputs