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
@@ -157,6 +158,23 @@ def build_plan(
         optimizers: Sequence[DataflowPlanOptimizer] = (),
     ) -> DataflowPlan:
         """Generate a plan for reading the results of a query with the given spec into a dataframe or table."""
+        # Workaround for a Pycharm type inspection issue with decorators.
+        # noinspection PyArgumentList
+        return self._build_plan(
+            query_spec=query_spec,
+            output_sql_table=output_sql_table,
+            output_selection_specs=output_selection_specs,
+            optimizers=optimizers,
+        )
+
+    @log_runtime()
+    def _build_plan(
+        self,
+        query_spec: MetricFlowQuerySpec,
+        output_sql_table: Optional[SqlTable],
+        output_selection_specs: Optional[InstanceSpecSet],
+        optimizers: Sequence[DataflowPlanOptimizer],
+    ) -> DataflowPlan:
         for metric_spec in query_spec.metric_specs:
             if (
                 len(metric_spec.filter_specs) > 0
@@ -588,8 +606,13 @@ def build_plan_for_distinct_values(self, query_spec: MetricFlowQuerySpec) -> Dat
 
         e.g. distinct listing__country_latest for bookings by listing__country_latest
         """
-        assert not query_spec.metric_specs, "Can't build distinct values plan with metrics."
+        # Workaround for a Pycharm type inspection issue with decorators.
+        # noinspection PyArgumentList
+        return self._build_plan_for_distinct_values(query_spec)
 
+    @log_runtime()
+    def _build_plan_for_distinct_values(self, query_spec: MetricFlowQuerySpec) -> DataflowPlan:
+        assert not query_spec.metric_specs, "Can't build distinct values plan with metrics."
         query_level_filter_specs: Sequence[WhereFilterSpec] = ()
         if query_spec.filter_intersection is not None and len(query_spec.filter_intersection.where_filters) > 0:
             filter_spec_factory = WhereSpecFactory(

metricflow/mf_logging/runtime.py

@@ -0,0 +1,45 @@
+from __future__ import annotations
+
+import functools
+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]:
+        # wraps() preserves attributes like the __qualname__ and the docstring in the returned function.
+        @functools.wraps(wrapped_function)
+        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
@@ -74,11 +75,16 @@ def __init__(  # noqa: D
 
     def resolve_lookup(self) -> FilterSpecResolutionLookUp:
         """Find all where filters and return a lookup that provides the specs for the included group-by-items."""
+        # Workaround for a Pycharm type inspection issue with decorators.
+        # noinspection PyArgumentList
+        return self._resolve_lookup()
+
+    @log_runtime()
+    def _resolve_lookup(self) -> FilterSpecResolutionLookUp:
         visitor = _ResolveWhereFilterSpecVisitor(
             manifest_lookup=self._manifest_lookup,
             spec_pattern_factory=self.spec_pattern_factory,
         )
-
         return self._resolution_dag.sink_node.accept(visitor)
 
 

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
@@ -318,6 +319,39 @@ def parse_and_validate_query(
 
         e.g. make sure that the given metric is a valid metric name.
         """
+        # Workaround for a Pycharm type inspection issue with decorators.
+        # noinspection PyArgumentList
+        return self._parse_and_validate_query(
+            metric_names=metric_names,
+            metrics=metrics,
+            group_by_names=group_by_names,
+            group_by=group_by,
+            limit=limit,
+            time_constraint_start=time_constraint_start,
+            time_constraint_end=time_constraint_end,
+            where_constraint=where_constraint,
+            where_constraint_str=where_constraint_str,
+            order_by_names=order_by_names,
+            order_by=order_by,
+            min_max_only=min_max_only,
+        )
+
+    @log_runtime()
+    def _parse_and_validate_query(
+        self,
+        metric_names: Optional[Sequence[str]],
+        metrics: Optional[Sequence[MetricQueryParameter]],
+        group_by_names: Optional[Sequence[str]],
+        group_by: Optional[Tuple[GroupByParameter, ...]],
+        limit: Optional[int],
+        time_constraint_start: Optional[datetime.datetime],
+        time_constraint_end: Optional[datetime.datetime],
+        where_constraint: Optional[WhereFilter],
+        where_constraint_str: Optional[str],
+        order_by_names: Optional[Sequence[str]],
+        order_by: Optional[Sequence[OrderByQueryParameter]],
+        min_max_only: bool,
+    ) -> MetricFlowQuerySpec:
         # TODO: validate min_max_only - can only be called for non-metric queries
         assert_at_most_one_arg_set(metric_names=metric_names, metrics=metrics)
         assert_at_most_one_arg_set(group_by_names=group_by_names, group_by=group_by)

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_pattern_factory import WhereFilterPatternFactory
@@ -328,6 +329,12 @@ def _build_filter_spec_lookup(
 
     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."""
+        # Workaround for a Pycharm type inspection issue with decorators.
+        # noinspection PyArgumentList
+        return self._resolve_query(resolver_input_for_query=resolver_input_for_query)
+
+    @log_runtime()
+    def _resolve_query(self, resolver_input_for_query: ResolverInputForQuery) -> MetricFlowQueryResolution:
         metric_inputs = resolver_input_for_query.metric_inputs
         group_by_item_inputs = resolver_input_for_query.group_by_item_inputs
         order_by_item_inputs = resolver_input_for_query.order_by_item_inputs