Add logging to track latency for metrics as dimensions in query parsing

metricflow-semantics/metricflow_semantics/model/semantics/linkable_spec_resolver.py

@@ -186,6 +186,7 @@ def __init__(
 
         # Populate storage dicts with linkable metrics. This loop must happen after the one above so that
         # _metric_to_linkable_element_sets is populated with entities and dimensions.
+        linkable_metrics_start_time = time.time()
         for metric in self._semantic_manifest.metrics:
             # Cumulative metrics and time offset metrics require grouping by metric_time, which is not yet available for
             # linkable metrics. So skip those.
@@ -218,13 +219,17 @@ def __init__(
         # If no metrics are specified, the query interface supports querying distinct values for dimensions, entities,
         # and group by metrics.
         linkable_element_sets_for_no_metrics_queries: List[LinkableElementSet] = []
+        # Temp: separate loop to track latency for linkable metrics. TODO: combine with loop below.
         for semantic_model in semantic_manifest.semantic_models:
-            linkable_element_sets_for_no_metrics_queries.append(self._get_elements_in_semantic_model(semantic_model))
             linkable_element_sets_for_no_metrics_queries.append(
                 self.get_joinable_metrics_for_semantic_model(
                     semantic_model, SemanticModelJoinPath(left_semantic_model_reference=semantic_model.reference)
                 )
             )
+        logger.info(f"Building valid linkable metrics took: {time.time() - linkable_metrics_start_time:.2f}s")
+
+        for semantic_model in semantic_manifest.semantic_models:
+            linkable_element_sets_for_no_metrics_queries.append(self._get_elements_in_semantic_model(semantic_model))
 
         metric_time_elements_for_no_metrics = self._get_metric_time_elements(measure_reference=None)
         self._no_metric_linkable_element_set = LinkableElementSet.merge_by_path_key(

metricflow-semantics/metricflow_semantics/model/semantics/metric_lookup.py

@@ -1,6 +1,7 @@
 from __future__ import annotations
 
 import logging
+import time
 from typing import Dict, FrozenSet, Optional, Sequence, Set
 
 from dbt_semantic_interfaces.enum_extension import assert_values_exhausted
@@ -53,11 +54,17 @@ def linkable_elements_for_measure(
         frozen_with_any_of = LinkableElementProperty.all_properties() if with_any_of is None else frozenset(with_any_of)
         frozen_without_any_of = frozenset() if without_any_of is None else frozenset(without_any_of)
 
-        return self._linkable_spec_resolver.get_linkable_element_set_for_measure(
+        start_time = time.time()
+        linkable_element_set = self._linkable_spec_resolver.get_linkable_element_set_for_measure(
             measure_reference=measure_reference,
             with_any_of=frozen_with_any_of,
             without_any_of=frozen_without_any_of,
         )
+        logger.info(
+            f"Getting valid linkable elements for measure '{measure_reference.element_name}' took: {time.time() - start_time:.2f}s"
+        )
+
+        return linkable_element_set
 
     def linkable_elements_for_no_metrics_query(
         self,

metricflow-semantics/metricflow_semantics/query/group_by_item/candidate_push_down/push_down_visitor.py

@@ -1,6 +1,7 @@
 from __future__ import annotations
 
 import logging
+import time
 from contextlib import contextmanager
 from dataclasses import dataclass
 from typing import Dict, Iterator, List, Optional, Sequence, Set, Tuple
@@ -189,9 +190,11 @@ def visit_measure_node(self, node: MeasureGroupByItemSourceNode) -> PushDownResu
             else:
                 assert_values_exhausted(metric.type)
 
+            start_time = time.time()
             matching_items = items_available_for_measure.filter_by_spec_patterns(
                 patterns_to_apply + self._source_spec_patterns
             )
+            logger.info(f"Filtering valid linkable elements took: {time.time() - start_time:.2f}s")
 
             if logger.isEnabledFor(logging.DEBUG):
                 logger.debug(