Repository: scoutapp/scout_apm_python
Pull request #252 (2019-09-14 21:33:26)

Add start and stop allocations to each span, to support timeline trace


Patch:
diff --git a/CHANGELOG.md b/CHANGELOG.md
index d2b03f9..88bc388 100644
--- a/CHANGELOG.md
+++ b/CHANGELOG.md
@@ -9,6 +9,8 @@
   ([PR #240](https://github.com/scoutapp/scout_apm_python/pull/240)).
 - Fix CPU statistics to work when the CPU count cannot be determined
   ([PR #245](https://github.com/scoutapp/scout_apm_python/pull/245)).
+- Support timeline trace view
+  ([PR #252](https://github.com/scoutapp/scout_apm_python/pull/252)).
 
 ## [2.4.1] 2019-08-26
 
diff --git a/src/scout_apm/core/tracked_request.py b/src/scout_apm/core/tracked_request.py
index 39a8260..11d6d4d 100644
--- a/src/scout_apm/core/tracked_request.py
+++ b/src/scout_apm/core/tracked_request.py
@@ -172,7 +172,7 @@ class Span(object):
     # Add any interesting annotations to the span. Assumes that we are in the
     # process of stopping this span.
     def annotate(self):
-        self.tag("allocations", self.calculate_allocations())
+        self.add_allocation_tags()
         # Don't capture backtraces for Controller or Middleware
         if self.operation is not None and (
             self.operation.startswith(("Controller", "Middleware"))
@@ -183,9 +183,9 @@ class Span(object):
         if self.duration() > slow_threshold:
             self.capture_backtrace()
 
-    def calculate_allocations(self):
+    def add_allocation_tags(self):
         if objtrace is None:
-            return 0
+            return
 
         start_allocs = (
             self.start_objtrace_counts[0]
@@ -197,24 +197,24 @@ class Span(object):
             + self.end_objtrace_counts[1]
             + self.end_objtrace_counts[2]
         )
-        try:
-            # If even one of the counters rolled over, we're pretty much
-            # guaranteed to have end_allocs be less than start_allocs.
-            # This should rarely happen. Max Unsigned Long Long is a big number
-            if end_allocs - start_allocs < 0:
-                logger.debug(
-                    "End allocation count smaller than start allocation "
-                    "count for span %s: start = %d, end = %d",
-                    self.span_id,
-                    start_allocs,
-                    end_allocs,
-                )
-                return 0
-            return end_allocs - start_allocs
-        except TypeError as e:
-            logger.debug("Exception in calculate_allocations: %r", e)
+
+        # If even one of the counters rolled over, we're pretty much
+        # guaranteed to have end_allocs be less than start_allocs.
+        # This should rarely happen. Max Unsigned Long Long is a big number
+        if end_allocs - start_allocs < 0:
+            logger.debug(
+                "End allocation count smaller than start allocation "
+                "count for span %s: start = %d, end = %d",
+                self.span_id,
+                start_allocs,
+                end_allocs,
+            )
             return 0
 
+        self.tag("allocations", end_allocs - start_allocs)
+        self.tag("start_allocations", start_allocs)
+        self.tag("stop_allocations", end_allocs)
+
     def capture_backtrace(self):
         stack = scout_apm.core.backtrace.capture()
         self.tag("stack", stack)


Test patch:
diff --git a/tests/unit/core/test_commands.py b/tests/unit/core/test_commands.py
index 3097db8..022c560 100644
--- a/tests/unit/core/test_commands.py
+++ b/tests/unit/core/test_commands.py
@@ -8,6 +8,11 @@ import pytest
 from scout_apm.core import commands
 from scout_apm.core.tracked_request import TrackedRequest
 
+try:
+    from scout_apm.core import objtrace
+except ImportError:
+    objtrace = None
+
 REQUEST_ID = "req-97c1d72c-5519-4665-85d3-1ac21af39b63"
 SPAN_ID = "span-7dbb0712-e3c5-4b73-b317-f8d2114c5993"
 PARENT_ID = "span-d10de59e-1e9f-46e9-9d5e-81b5bfc091ec"
@@ -241,6 +246,10 @@ def make_tracked_request_instance_deterministic(tr):
 
         if "allocations" in span.tags:
             span.tags["allocations"] = 0
+        if "start_allocations" in span.tags:
+            span.tags["start_allocations"] = 0
+        if "stop_allocations" in span.tags:
+            span.tags["stop_allocations"] = 0
 
 
 def test_batch_command_from_tracked_request():
@@ -302,52 +311,104 @@ def test_batch_command_from_tracked_request_with_tag():
     }
 
 
+@pytest.mark.skipif(
+    objtrace is None, reason="Allocation tags only there when objtrace works"
+)
 def test_batch_command_from_tracked_request_with_span():
     tr = TrackedRequest()
     tr.start_span()
     tr.stop_span()
     make_tracked_request_instance_deterministic(tr)
+
     command = commands.BatchCommand.from_tracked_request(tr)
-    assert command.message() == {
-        "BatchCommand": {
-            "commands": [
-                {
-                    "StartRequest": {
-                        "request_id": REQUEST_ID,
-                        "timestamp": START_TIME_STR,
-                    }
-                },
-                {
-                    "StartSpan": {
-                        "operation": None,
-                        "parent_id": None,
-                        "request_id": REQUEST_ID,
-                        "span_id": SPAN_ID,
-                        "timestamp": START_TIME_STR,
-                    }
-                },
-                {
-                    "TagSpan": {
-                        "request_id": REQUEST_ID,
-                        "span_id": SPAN_ID,
-                        "tag": "allocations",
-                        "timestamp": START_TIME_STR,
-                        "value": 0,
-                    }
-                },
-                {
-                    "StopSpan": {
-                        "request_id": REQUEST_ID,
-                        "span_id": SPAN_ID,
-                        "timestamp": END_TIME_STR,
-                    }
-                },
-                {
-                    "FinishRequest": {
-                        "request_id": REQUEST_ID,
-                        "timestamp": END_TIME_STR,
-                    }
-                },
-            ]
+
+    message_commands = command.message()["BatchCommand"]["commands"]
+    assert len(message_commands) == 7
+    assert message_commands[0] == {
+        "StartRequest": {"request_id": REQUEST_ID, "timestamp": START_TIME_STR}
+    }
+    assert message_commands[1] == {
+        "StartSpan": {
+            "operation": None,
+            "parent_id": None,
+            "request_id": REQUEST_ID,
+            "span_id": SPAN_ID,
+            "timestamp": START_TIME_STR,
+        }
+    }
+    assert sorted(message_commands[2:5], key=lambda c: c["TagSpan"]["tag"]) == [
+        {
+            "TagSpan": {
+                "request_id": REQUEST_ID,
+                "span_id": SPAN_ID,
+                "tag": "allocations",
+                "timestamp": START_TIME_STR,
+                "value": 0,
+            }
+        },
+        {
+            "TagSpan": {
+                "request_id": REQUEST_ID,
+                "span_id": SPAN_ID,
+                "tag": "start_allocations",
+                "timestamp": START_TIME_STR,
+                "value": 0,
+            }
+        },
+        {
+            "TagSpan": {
+                "request_id": REQUEST_ID,
+                "span_id": SPAN_ID,
+                "tag": "stop_allocations",
+                "timestamp": START_TIME_STR,
+                "value": 0,
+            }
+        },
+    ]
+    assert message_commands[5] == {
+        "StopSpan": {
+            "request_id": REQUEST_ID,
+            "span_id": SPAN_ID,
+            "timestamp": END_TIME_STR,
         }
     }
+    assert message_commands[6] == {
+        "FinishRequest": {"request_id": REQUEST_ID, "timestamp": END_TIME_STR}
+    }
+
+
+@pytest.mark.skipif(
+    objtrace is not None, reason="Allocation tags only there when objtrace works"
+)
+def test_batch_command_from_tracked_request_with_span_no_objtrace():
+    tr = TrackedRequest()
+    tr.start_span()
+    tr.stop_span()
+    make_tracked_request_instance_deterministic(tr)
+
+    command = commands.BatchCommand.from_tracked_request(tr)
+
+    message_commands = command.message()["BatchCommand"]["commands"]
+    assert len(message_commands) == 4
+    assert message_commands[0] == {
+        "StartRequest": {"request_id": REQUEST_ID, "timestamp": START_TIME_STR}
+    }
+    assert message_commands[1] == {
+        "StartSpan": {
+            "operation": None,
+            "parent_id": None,
+            "request_id": REQUEST_ID,
+            "span_id": SPAN_ID,
+            "timestamp": START_TIME_STR,
+        }
+    }
+    assert message_commands[2] == {
+        "StopSpan": {
+            "request_id": REQUEST_ID,
+            "span_id": SPAN_ID,
+            "timestamp": END_TIME_STR,
+        }
+    }
+    assert message_commands[3] == {
+        "FinishRequest": {"request_id": REQUEST_ID, "timestamp": END_TIME_STR}
+    }