Browse Source

fix(trace): Return timestamps on performance issues (#66537)

- The code for performance issue timestamps was just wrong and untested
sorry lol
- This calculates the precise timestamps for spans and uses that for
performance issues. From testing this should be a very minor performance
change
William Mak 1 year ago
parent
commit
7b61005a4e

+ 15 - 14
src/sentry/api/endpoints/organization_events_trace.py

@@ -212,19 +212,16 @@ class TraceEvent:
                         offender_span_ids = problem.evidence_data.get("offender_span_ids", [])
                         if event_span.get("span_id") in offender_span_ids:
                             try:
-                                end_timestamp = float(event_span.get("timestamp"))
+                                start_timestamp = float(event_span.get("precise.start_ts"))
+                                if start is None:
+                                    start = start_timestamp
+                                else:
+                                    start = min(start, start_timestamp)
+                                end_timestamp = float(event_span.get("precise.finish_ts"))
                                 if end is None:
                                     end = end_timestamp
                                 else:
                                     end = max(end, end_timestamp)
-                                if end_timestamp is not None:
-                                    start_timestamp = float(
-                                        end_timestamp - event_span.get("span.duration")
-                                    )
-                                    if start is None:
-                                        start = start_timestamp
-                                    else:
-                                        start = min(start, start_timestamp)
                             except ValueError:
                                 pass
                             suspect_spans.append(event_span.get("span_id"))
@@ -530,9 +527,10 @@ def build_span_query(trace_id, spans_params, query_spans):
         selected_columns=[
             "transaction.id",
             "span_id",
-            "timestamp",
+            "precise.start_ts",
+            "precise.finish_ts",
         ],
-        orderby=["timestamp", "id"],
+        orderby=["precise.start_ts", "id"],
         limit=10000,
     )
     # Building the condition manually, a performance optimization since we might put thousands of span ids
@@ -666,18 +664,21 @@ def augment_transactions_with_spans(
             # not a root span), see if the indexed spans data can tell us what the parent
             # transaction id is.
             if "trace.parent_span.stripped" in transaction:
-                if parent := parent_map.get(transaction["trace.parent_span.stripped"]):
+                parent = parent_map.get(transaction["trace.parent_span.stripped"])
+                if parent is not None:
                     transaction["trace.parent_transaction"] = parent["transaction.id"]
     with sentry_sdk.start_span(op="augment.transactions", description="linking perf issues"):
         for problem in issue_occurrences:
             for span_id in problem.evidence_data["offender_span_ids"]:
-                if parent := parent_map.get(span_id):
+                parent = parent_map.get(span_id)
+                if parent is not None:
                     transaction = transaction_problem_map[problem.event_id]
                     transaction["occurrence_spans"].append(parent)
                     transaction["issue_occurrences"].append(problem)
     with sentry_sdk.start_span(op="augment.transactions", description="linking errors"):
         for error in errors:
-            if parent := parent_map.get(error["trace.span"]):
+            parent = parent_map.get(error["trace.span"])
+            if parent is not None:
                 error["trace.transaction"] = parent["transaction.id"]
     return transactions
 

+ 6 - 22
src/sentry/search/events/datasets/discover.py

@@ -158,8 +158,12 @@ class DiscoverDatasetConfig(DatasetConfig):
             TOTAL_COUNT_ALIAS: self._resolve_total_count,
             TOTAL_TRANSACTION_DURATION_ALIAS: self._resolve_total_sum_transaction_duration,
             DEVICE_CLASS_ALIAS: self._resolve_device_class,
-            PRECISE_FINISH_TS: self._resolve_precise_finish_ts,
-            PRECISE_START_TS: self._resolve_precise_start_ts,
+            PRECISE_FINISH_TS: lambda alias: field_aliases.resolve_precise_timestamp(
+                Column("finish_ts"), Column("finish_ms"), alias
+            ),
+            PRECISE_START_TS: lambda alias: field_aliases.resolve_precise_timestamp(
+                Column("start_ts"), Column("start_ms"), alias
+            ),
         }
 
     @property
@@ -1408,26 +1412,6 @@ class DiscoverDatasetConfig(DatasetConfig):
             DEVICE_CLASS_ALIAS,
         )
 
-    def _resolve_precise_start_ts(self, alias: str) -> SelectType:
-        return Function(
-            "plus",
-            [
-                Function("toUnixTimestamp", [Column("start_ts")]),
-                Function("divide", [Column("start_ms"), 1000]),
-            ],
-            alias,
-        )
-
-    def _resolve_precise_finish_ts(self, alias: str) -> SelectType:
-        return Function(
-            "plus",
-            [
-                Function("toUnixTimestamp", [Column("finish_ts")]),
-                Function("divide", [Column("finish_ms"), 1000]),
-            ],
-            alias,
-        )
-
     # Functions
     def _resolve_apdex_function(self, args: Mapping[str, str], alias: str) -> SelectType:
         if args["satisfaction"]:

+ 11 - 0
src/sentry/search/events/datasets/field_aliases.py

@@ -135,3 +135,14 @@ def resolve_device_class(builder: builder.QueryBuilder, alias: str) -> SelectTyp
         [builder.column("device.class"), values, keys, "Unknown"],
         alias,
     )
+
+
+def resolve_precise_timestamp(timestamp_column, ms_column, alias: str) -> SelectType:
+    return Function(
+        "plus",
+        [
+            Function("toUnixTimestamp", [timestamp_column]),
+            Function("divide", [ms_column, 1000]),
+        ],
+        alias,
+    )

+ 6 - 0
src/sentry/search/events/datasets/spans_indexed.py

@@ -51,6 +51,12 @@ class SpansIndexedDatasetConfig(DatasetConfig):
                 self.builder, alias
             ),
             "span.duration": self._resolve_span_duration,
+            constants.PRECISE_FINISH_TS: lambda alias: field_aliases.resolve_precise_timestamp(
+                Column("end_timestamp"), Column("end_ms"), alias
+            ),
+            constants.PRECISE_START_TS: lambda alias: field_aliases.resolve_precise_timestamp(
+                Column("start_timestamp"), Column("start_ms"), alias
+            ),
         }
 
     @property

+ 22 - 2
tests/snuba/api/endpoints/test_organization_events_trace.py

@@ -83,7 +83,9 @@ class OrganizationEventsTraceEndpointBase(OrganizationEventsEndpointTestBase):
                         span.update({"event_id": event.event_id})
                         self.store_span(
                             self.create_span(
-                                span, start_ts=datetime.fromtimestamp(span["start_timestamp"])
+                                span,
+                                start_ts=datetime.fromtimestamp(span["start_timestamp"]),
+                                duration=int(span["timestamp"] - span["start_timestamp"]) * 1000,
                             )
                         )
                 self.store_span(self.convert_event_data_to_span(event))
@@ -810,7 +812,11 @@ class OrganizationEventsTraceEndpointTest(OrganizationEventsTraceEndpointBase):
         assert root["transaction.duration"] == 3000
         assert len(root["children"]) == 3
         assert len(root["performance_issues"]) == 1
-        assert root["performance_issues"][0]["suspect_spans"][0] == self.root_span_ids[0]
+        # The perf issue is put on the first span
+        perf_issue_span = self.root_event.data["spans"][0]
+        assert root["performance_issues"][0]["suspect_spans"][0] == perf_issue_span["span_id"]
+        assert root["performance_issues"][0]["start"] == perf_issue_span["start_timestamp"]
+        assert root["performance_issues"][0]["end"] == perf_issue_span["timestamp"]
 
         for i, gen1 in enumerate(root["children"]):
             self.assert_event(gen1, self.gen1_events[i], f"gen1_{i}")
@@ -1606,6 +1612,20 @@ class OrganizationEventsTraceEndpointTestUsingSpans(OrganizationEventsTraceEndpo
 
         assert response.status_code == 200, response.content
 
+    def test_simple(self):
+        self.load_trace()
+        with self.feature(self.FEATURES):
+            response = self.client_get(
+                data={"project": -1},
+            )
+        assert response.status_code == 200, response.content
+        trace_transaction = response.data["transactions"][0]
+        self.assert_trace_data(trace_transaction)
+        # We shouldn't have detailed fields here
+        assert "transaction.status" not in trace_transaction
+        assert "tags" not in trace_transaction
+        assert "measurements" not in trace_transaction
+
 
 @region_silo_test
 class OrganizationEventsTraceMetaEndpointTest(OrganizationEventsTraceEndpointBase):