ref(profiling): Use the transaction timestamps to anchor the profile (#1898)

We want the profile to be as closely aligned with the transaction's timestamps
as possible to make aligning the two visualizations as accurate as possible.
Here we change the transaction's internal `_start_timestamp_monotonic` to
contain an unit for each of the possible clocks we use in the various python
versions. This allows us to use the `start_timestamp` of the transaction as the
timestamp of the profile, and we can use the `_start_timestamp_monontonic` as
the anchor for all the relative timestamps in the profile.

Co-authored-by: Neel Shah <[email protected]>

Author: Zylphrex

sentry_sdk/profiler.py

@@ -426,7 +426,11 @@ def __init__(
         self._default_active_thread_id = get_current_thread_id() or 0  # type: int
         self.active_thread_id = None  # type: Optional[int]
 
-        self.start_ns = 0  # type: int
+        try:
+            self.start_ns = transaction._start_timestamp_monotonic_ns  # type: int
+        except AttributeError:
+            self.start_ns = 0
+
         self.stop_ns = 0  # type: int
         self.active = False  # type: bool
 
@@ -524,7 +528,8 @@ def start(self):
         assert self.scheduler, "No scheduler specified"
         logger.debug("[Profiling] Starting profile")
         self.active = True
-        self.start_ns = nanosecond_time()
+        if not self.start_ns:
+            self.start_ns = nanosecond_time()
         self.scheduler.start_profiling(self)
 
     def stop(self):
@@ -643,7 +648,7 @@ def to_json(self, event_opt, options):
             "platform": "python",
             "profile": profile,
             "release": event_opt.get("release", ""),
-            "timestamp": event_opt["timestamp"],
+            "timestamp": event_opt["start_timestamp"],
             "version": "1",
             "device": {
                 "architecture": platform.machine(),

sentry_sdk/tracing.py

@@ -1,12 +1,11 @@
 import uuid
 import random
-import time
 
 from datetime import datetime, timedelta
 
 import sentry_sdk
 from sentry_sdk.consts import INSTRUMENTER
-from sentry_sdk.utils import logger
+from sentry_sdk.utils import logger, nanosecond_time
 from sentry_sdk._types import MYPY
 
 
@@ -87,7 +86,7 @@ class Span(object):
         "op",
         "description",
         "start_timestamp",
-        "_start_timestamp_monotonic",
+        "_start_timestamp_monotonic_ns",
         "status",
         "timestamp",
         "_tags",
@@ -142,11 +141,9 @@ def __init__(
         self._containing_transaction = containing_transaction
         self.start_timestamp = start_timestamp or datetime.utcnow()
         try:
-            # TODO: For Python 3.7+, we could use a clock with ns resolution:
-            # self._start_timestamp_monotonic = time.perf_counter_ns()
-
-            # Python 3.3+
-            self._start_timestamp_monotonic = time.perf_counter()
+            # profiling depends on this value and requires that
+            # it is measured in nanoseconds
+            self._start_timestamp_monotonic_ns = nanosecond_time()
         except AttributeError:
             pass
 
@@ -483,9 +480,9 @@ def finish(self, hub=None, end_timestamp=None):
             if end_timestamp:
                 self.timestamp = end_timestamp
             else:
-                duration_seconds = time.perf_counter() - self._start_timestamp_monotonic
+                elapsed = nanosecond_time() - self._start_timestamp_monotonic_ns
                 self.timestamp = self.start_timestamp + timedelta(
-                    seconds=duration_seconds
+                    microseconds=elapsed / 1000
                 )
         except AttributeError:
             self.timestamp = datetime.utcnow()

sentry_sdk/utils.py

@@ -1173,12 +1173,10 @@ def nanosecond_time():
 
     def nanosecond_time():
         # type: () -> int
-
         return int(time.perf_counter() * 1e9)
 
 else:
 
     def nanosecond_time():
         # type: () -> int
-
         raise AttributeError