added option to not collect frames for short spans (#142)

closes #142

CHANGELOG.asciidoc

@@ -14,6 +14,7 @@ https://github.com/elastic/apm-agent-python/compare/v2.0.1\...master[Check the H
 
  * made skipping of initial `elasticapm` frames for span stack traces more generic ({pull}167[#167])
  * added `context.process.ppid` field (supported in apm-server 6.3+) ({pull}168[#168])
+ * added option to disable stack frame collection for very short spans ({pull}142[#142])
 
 [[release-2.0.1]]
 [float]

docs/configuration.asciidoc

@@ -368,6 +368,24 @@ Limits the amount of spans that are recorded per transaction.
 This is helpful in cases where a transaction creates a very high amount of spans (e.g. thousands of SQL queries).
 Setting an upper limit will prevent overloading the agent and the APM server with too much work for such edge cases.
 
+[float]
+[[config-span-frames-min-duration-ms]]
+==== `span_frames_min_duration_ms`
+
+|============
+| Environment                               | Django/Flask                  | Default
+| `ELASTIC_APM_SPAN_FRAMES_MIN_DURATION_MS` | `SPAN_FRAMES_MIN_DURATION_MS` | `-1`
+|============
+
+In its default settings, the APM agent will collect a stack trace with every recorded span.
+While this is very helpful to find the exact place in your code that causes the span,
+collecting this stack trace does have some overhead.
+
+With the default setting, `-1`, stack traces will be collected for all spans.
+Setting it to a positive value, e.g. `5`, will limit stack trace collection to spans
+with durations equal or longer than the given value in milliseconds, e.g. 5 milliseconds.
+
+To disable stack trace collection for spans completely, set the value to 0.
 
 [float]
 [[config-max-queue-size]]

docs/tuning.asciidoc

@@ -73,3 +73,11 @@ In some cases however, the number of spans can explode:
 To avoid that such edge cases overload both the agent and the APM Server,
 the agent stops recording spans when a limit is reached.
 You can configure this limit by changing the <<config-transaction-max-spans,`transaction_max_spans`>> setting.
+
+Another option to reduce overhead of collecting contextual data for spans is to disable collection for very short spans.
+While this contextual data (specifically, the stack trace) can be very useful to pinpoint where exectly the span is caused in your code,
+it is less interesting for very short spans.
+You can define a minimal threshold for span duration in milliseconds,
+using the <<config-span-frames-min-duration-ms,`span_frames_min_duration_ms`>> setting.
+If a span takes less than this duration, no stack frames will be collected for this span.
+Other contextual information, like the SQL query, will still be available.

elasticapm/base.py

@@ -154,6 +154,7 @@ def frames_collector_func():
             collect_frequency=self.config.flush_interval,
             sample_rate=self.config.transaction_sample_rate,
             max_spans=self.config.transaction_max_spans,
+            span_frames_min_duration=self.config.span_frames_min_duration_ms,
             max_queue_size=self.config.max_queue_size,
             ignore_patterns=self.config.transactions_ignore_patterns,
         )

elasticapm/conf/__init__.py

@@ -158,6 +158,7 @@ class Config(_ConfigBase):
     flush_interval = _ConfigValue('FLUSH_INTERVAL', type=int, default=10)
     transaction_sample_rate = _ConfigValue('TRANSACTION_SAMPLE_RATE', type=float, default=1.0)
     transaction_max_spans = _ConfigValue('TRANSACTION_MAX_SPANS', type=int, default=500)
+    span_frames_min_duration_ms = _ConfigValue('SPAN_FRAMES_MIN_DURATION', default=5, type=int)
     max_queue_size = _ConfigValue('MAX_QUEUE_SIZE', type=int, default=500)
     collect_local_variables = _ConfigValue('COLLECT_LOCAL_VARIABLES', default='errors')
     source_lines_error_app_frames = _ConfigValue('SOURCE_LINES_ERROR_APP_FRAMES', type=int, default=5)

elasticapm/traces.py

@@ -42,7 +42,8 @@ def get_transaction(clear=False):
 
 
 class Transaction(object):
-    def __init__(self, frames_collector_func, transaction_type="custom", is_sampled=True, max_spans=None):
+    def __init__(self, frames_collector_func, transaction_type="custom", is_sampled=True, max_spans=None,
+                 span_frames_min_duration=None):
         self.id = str(uuid.uuid4())
         self.timestamp = datetime.datetime.utcnow()
         self.start_time = _time_func()
@@ -55,6 +56,7 @@ def __init__(self, frames_collector_func, transaction_type="custom", is_sampled=
         self.spans = []
         self.span_stack = []
         self.max_spans = max_spans
+        self.span_frames_min_duration = span_frames_min_duration
         self.dropped_spans = 0
         self.ignore_subtree = False
         self.context = {}
@@ -103,7 +105,8 @@ def end_span(self, skip_frames):
         if self.span_stack:
             span.parent = self.span_stack[-1].idx
 
-        span.frames = self._frames_collector_func()[skip_frames:]
+        if not self.span_frames_min_duration or span.duration >= self.span_frames_min_duration:
+            span.frames = self._frames_collector_func()[skip_frames:]
         self.spans.append(span)
 
         return span
@@ -129,8 +132,9 @@ def to_dict(self):
 
 
 class Span(object):
-    def __init__(self, idx, name, span_type, start_time, context=None,
-                 leaf=False):
+    __slots__ = ('idx', 'name', 'type', 'context', 'leaf', 'start_time', 'duration', 'parent', 'frames')
+
+    def __init__(self, idx, name, span_type, start_time, context=None, leaf=False):
         """
         Create a new Span
 
@@ -148,14 +152,9 @@ def __init__(self, idx, name, span_type, start_time, context=None,
         self.leaf = leaf
         self.start_time = start_time
         self.duration = None
-        self.transaction = None
         self.parent = None
         self.frames = None
 
-    @property
-    def fingerprint(self):
-        return self.transaction, self.parent, self.name, self.type
-
     def to_dict(self):
         return {
             'id': self.idx,
@@ -171,7 +170,7 @@ def to_dict(self):
 
 class TransactionsStore(object):
     def __init__(self, frames_collector_func, collect_frequency, sample_rate=1.0, max_spans=0, max_queue_size=None,
-                 ignore_patterns=None):
+                 span_frames_min_duration=None, ignore_patterns=None):
         self.cond = threading.Condition()
         self.collect_frequency = collect_frequency
         self.max_queue_size = max_queue_size
@@ -181,6 +180,11 @@ def __init__(self, frames_collector_func, collect_frequency, sample_rate=1.0, ma
         self._last_collect = _time_func()
         self._ignore_patterns = [re.compile(p) for p in ignore_patterns or []]
         self._sample_rate = sample_rate
+        if span_frames_min_duration in (-1, None):
+            # both None and -1 mean "no minimum"
+            self.span_frames_min_duration = None
+        else:
+            self.span_frames_min_duration = span_frames_min_duration / 1000.0
 
     def add_transaction(self, transaction):
         with self.cond:
@@ -212,7 +216,7 @@ def begin_transaction(self, transaction_type):
         """
         is_sampled = self._sample_rate == 1.0 or self._sample_rate > random.random()
         transaction = Transaction(self._frames_collector_func, transaction_type, max_spans=self.max_spans,
-                                  is_sampled=is_sampled)
+                                  span_frames_min_duration=self.span_frames_min_duration, is_sampled=is_sampled)
         thread_local.transaction = transaction
         return transaction
 

tests/client/client_tests.py

@@ -663,6 +663,50 @@ def test_transaction_max_spans(should_collect, elasticapm_client):
     assert transaction['span_count'] == {'dropped': {'total': 10}}
 
 
+@pytest.mark.parametrize('elasticapm_client', [{'span_frames_min_duration_ms': 20}], indirect=True)
+@mock.patch('elasticapm.base.TransactionsStore.should_collect')
+def test_transaction_span_frames_min_duration(should_collect, elasticapm_client):
+    should_collect.return_value = False
+    elasticapm_client.begin_transaction('test_type')
+    with elasticapm.capture_span('noframes'):
+        time.sleep(0.001)
+    with elasticapm.capture_span('frames'):
+        time.sleep(0.040)
+    elasticapm_client.end_transaction('test')
+
+    transaction = elasticapm_client.instrumentation_store.get_all()[0]
+    spans = transaction['spans']
+
+    assert len(spans) == 2
+    assert spans[0]['name'] == 'noframes'
+    assert spans[0]['stacktrace'] is None
+
+    assert spans[1]['name'] == 'frames'
+    assert spans[1]['stacktrace'] is not None
+
+
+@pytest.mark.parametrize('elasticapm_client', [{'span_frames_min_durarion_ms': -1}], indirect=True)
+@mock.patch('elasticapm.base.TransactionsStore.should_collect')
+def test_transaction_span_frames_min_duration_no_limit(should_collect, elasticapm_client):
+    should_collect.return_value = False
+    elasticapm_client.begin_transaction('test_type')
+    with elasticapm.capture_span('frames'):
+        pass
+    with elasticapm.capture_span('frames'):
+        time.sleep(0.040)
+    elasticapm_client.end_transaction('test')
+
+    transaction = elasticapm_client.instrumentation_store.get_all()[0]
+    spans = transaction['spans']
+
+    assert len(spans) == 2
+    assert spans[0]['name'] == 'frames'
+    assert spans[0]['stacktrace'] is not None
+
+    assert spans[1]['name'] == 'frames'
+    assert spans[1]['stacktrace'] is not None
+
+
 @pytest.mark.parametrize('elasticapm_client', [{'transaction_max_spans': 3}], indirect=True)
 @mock.patch('elasticapm.base.TransactionsStore.should_collect')
 def test_transaction_max_span_nested(should_collect, elasticapm_client):

tests/contrib/django/fixtures.py

@@ -18,6 +18,9 @@ def send(self, url, **kwargs):
 @pytest.fixture()
 def django_elasticapm_client(request):
     client_config = getattr(request, 'param', {})
+    client_config.setdefault('service_name', 'app')
+    client_config.setdefault('secret_token', 'secret')
+    client_config.setdefault('span_frames_min_duration_ms', -1)
     app = apps.get_app_config('elasticapm.contrib.django')
     old_client = app.client
     client = TempStoreClient(**client_config)
@@ -41,6 +44,7 @@ def django_sending_elasticapm_client(request, validating_httpserver):
     client_config.setdefault('service_name', 'app')
     client_config.setdefault('secret_token', 'secret')
     client_config.setdefault('transport_class', 'elasticapm.transport.http.Transport')
+    client_config.setdefault('span_frames_min_duration_ms', -1)
     app = apps.get_app_config('elasticapm.contrib.django')
     old_client = app.client
     client = DjangoClient(**client_config)

tests/fixtures.py

@@ -72,6 +72,7 @@ def elasticapm_client(request):
     client_config.setdefault('service_name', 'myapp')
     client_config.setdefault('secret_token', 'test_key')
     client_config.setdefault('include_paths', ('*/tests/*',))
+    client_config.setdefault('span_frames_min_duration_ms', -1)
     client = TempStoreClient(**client_config)
     yield client
     client.close()
@@ -93,6 +94,7 @@ def sending_elasticapm_client(request, validating_httpserver):
     client_config.setdefault('service_name', 'myapp')
     client_config.setdefault('secret_token', 'test_key')
     client_config.setdefault('transport_class', 'elasticapm.transport.http.Transport')
+    client_config.setdefault('span_frames_min_duration_ms', -1)
     client_config.setdefault('include_paths', ('*/tests/*',))
     client = Client(**client_config)
     client.httpserver = validating_httpserver