Span stack trace min duration

CHANGELOG.asciidoc

@@ -38,6 +38,7 @@ endif::[]
 
 * Add OpenTelemetry API bridge {pull}1411[#1411]
 * Change default for `sanitize_field_names` to sanitize `*auth*` instead of `authorization` {pull}1494[#1494]
+* Add `span_stack_trace_min_duration` to replace deprecated `span_frames_min_duration` {pull}1498[#1498]
 
 [float]
 ===== Bug fixes

docs/configuration.asciidoc

@@ -666,6 +666,33 @@ while any positive integer value will be used as the maximum number of frames to
 To disable the limit and always capture all frames, set the value to `-1`.
 
 
+[float]
+[[config-span-stack-trace-min-duration]]
+==== `span_stack_trace_min_duration`
+
+<<dynamic-configuration, image:./images/dynamic-config.svg[] >>
+
+[options="header"]
+|============
+| Environment | Django/Flask | Default
+| `ELASTIC_APM_SPAN_STACK_TRACE_MIN_DURATION` | `SPAN_STACK_TRACE_MIN_DURATION` | `"5ms"`
+|============
+
+By default, the APM agent collects a stack trace with every recorded span
+that has a duration equal to or longer than this configured threshold. While
+stack traces are very helpful to find the exact place in your code from which a
+span originates, collecting this stack trace does have some overhead. Tune this
+threshold to ensure that you only collect stack traces for spans that
+could be problematic.
+
+To collect traces for all spans, regardless of their length, set the value to `0`.
+
+To disable stack trace collection for spans completely, set the value to `-1`.
+
+Except for the special values `-1` and `0`,
+this setting should be provided in *<<config-format-duration, duration format>>*.
+
+
 [float]
 [[config-span-frames-min-duration]]
 ==== `span_frames_min_duration`
@@ -678,18 +705,9 @@ To disable the limit and always capture all frames, set the value to `-1`.
 | `ELASTIC_APM_SPAN_FRAMES_MIN_DURATION` | `SPAN_FRAMES_MIN_DURATION` | `"5ms"`
 |============
 
-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.
-
-To collect traces for all spans, independent of the length, set the value to `-1`.
-Setting it to a positive value, e.g. `5ms`, will limit stack trace collection to spans
-with durations equal or longer than the given value.
+NOTE: This config value is being deprecated. Use
+<<config-span-stack-trace-min-duration,`span_stack_trace_min_duration`>> instead.
 
-To disable stack trace collection for spans completely, set the value to `0`.
-
-Except for the special values `-1` and `0`,
-this setting has to be provided in *<<config-format-duration, duration format>>*.
 
 [float]
 [[config-span-compression-enabled]]

docs/tuning.asciidoc

@@ -2,7 +2,7 @@
 == Performance tuning
 
 Using an APM solution comes with certain trade-offs, and the Python agent for Elastic APM is no different.
-Instrumenting your code, measuring timings, recording context data, etc., all need resources: 
+Instrumenting your code, measuring timings, recording context data, etc., all need resources:
 
  * CPU time
  * memory
@@ -67,24 +67,28 @@ In some cases, however, the number of spans can explode:
 
  * long-running transactions
  * unoptimized code, e.g. doing hundreds of SQL queries in a loop
- 
+
 To avoid these edge cases overloading both the agent and the APM Server,
 the agent stops recording spans when a specified limit is reached.
 You can configure this limit by changing the <<config-transaction-max-spans,`transaction_max_spans`>> setting.
 
-Another option to reduce the 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 exactly 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,`span_frames_min_duration`>> 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.
+[float]
+[[tuning-span-stack-trace-collection]]
+=== Span Stack Trace Collection
+
+Collecting stack traces for spans can be fairly costly from a performance standpoint.
+Stack traces are very useful for pinpointing which part of your code is generating a span;
+however, these stack traces are less useful for very short spans (as problematic spans tend to be longer).
+
+You can define a minimal threshold for span duration
+using the <<config-span-stack-trace-min-duration,`span_stack_trace_min_duration`>> setting.
+If a span's duration is less than this config value, no stack frames will be collected for this span.
 
 [float]
 [[tuning-frame-context]]
 === Collecting Frame Context
 
-When a stack trace is captured, the agent will also capture several lines of source code around each frame location in the stack trace. This allows the APM app to give greater insight into where exactly the error or span happens. 
+When a stack trace is captured, the agent will also capture several lines of source code around each frame location in the stack trace. This allows the APM app to give greater insight into where exactly the error or span happens.
 
 There are four settings you can modify to control this behavior:
 
@@ -93,7 +97,7 @@ There are four settings you can modify to control this behavior:
 * <<config-source-lines-span-app-frames,`source_lines_span_app_frames`>>
 * <<config-source-lines-span-library-frames,`source_lines_span_library_frames`>>
 
-As you can see, these settings are divided between app frames, which represent your application code, and library frames, which represent the code of your dependencies. Each of these categories are also split into separate error and span settings. 
+As you can see, these settings are divided between app frames, which represent your application code, and library frames, which represent the code of your dependencies. Each of these categories are also split into separate error and span settings.
 
 Reading source files inside a running application can cause a lot of disk I/O, and sending up source lines for each frame will have a network and storage cost that is quite high. Turning down these limits will help prevent excessive memory usage.
 

elasticapm/conf/__init__.py

@@ -317,7 +317,7 @@ def __call__(self, value, field_name):
  value = float(value)
  except ValueError:
  raise ConfigurationError("{} is not a float".format(value), field_name)
- multiplier = 10 ** self.precision
+ multiplier = 10**self.precision
  rounded = math.floor(value * multiplier + 0.5) / multiplier
  if rounded == 0 and self.minimum and value != 0:
  rounded = self.minimum
@@ -608,6 +608,9 @@ class Config(_ConfigBase):
  span_frames_min_duration = _DurationConfigValue(
  "SPAN_FRAMES_MIN_DURATION", default=timedelta(seconds=0.005), unitless_factor=0.001
  )
+ span_stack_trace_min_duration = _DurationConfigValue(
+ "SPAN_STACK_TRACE_MIN_DURATION", default=timedelta(seconds=0.005), unitless_factor=0.001
+ )
  span_compression_enabled = _BoolConfigValue("SPAN_COMPRESSION_ENABLED", default=False)
  span_compression_exact_match_max_duration = _DurationConfigValue(
  "SPAN_COMPRESSION_EXACT_MATCH_MAX_DURATION",

elasticapm/traces.py

@@ -34,6 +34,7 @@
 import threading
 import time
 import timeit
+import warnings
 from collections import defaultdict
 from datetime import timedelta
 from types import TracebackType
@@ -639,7 +640,11 @@ def end(self, skip_frames: int = 0, duration: Optional[float] = None):
  self.autofill_resource_context()
  super().end(skip_frames, duration)
  tracer = self.transaction.tracer
- if not tracer.span_frames_min_duration or self.duration >= tracer.span_frames_min_duration and self.frames:
+ if (
+ tracer.span_stack_trace_min_duration >= timedelta(seconds=0)
+ and self.duration >= tracer.span_stack_trace_min_duration
+ and self.frames
+ ):
  self.frames = tracer.frames_processing_func(self.frames)[skip_frames:]
  else:
  self.frames = None
@@ -821,11 +826,25 @@ def __init__(self, frames_collector_func, frames_processing_func, queue_func, co
  self._ignore_patterns = [re.compile(p) for p in config.transactions_ignore_patterns or []]
 
  @property
- def span_frames_min_duration(self) -> Optional[timedelta]:
- if self.config.span_frames_min_duration in (timedelta(seconds=-1), None):
- return None
+ def span_stack_trace_min_duration(self) -> timedelta:
+ if self.config.span_stack_trace_min_duration != timedelta(
+ seconds=0.005
+ ) or self.config.span_frames_min_duration == timedelta(seconds=0.005):
+ # No need to check span_frames_min_duration
+ return self.config.span_stack_trace_min_duration
  else:
- return self.config.span_frames_min_duration
+ # span_stack_trace_min_duration is default value and span_frames_min_duration is non-default.
+ # warn and use span_frames_min_duration
+ warnings.warn(
+ "`span_frames_min_duration` is deprecated. Please use `span_stack_trace_min_duration`.",
+ DeprecationWarning,
+ )
+ if self.config.span_frames_min_duration < timedelta(seconds=0):
+ return timedelta(seconds=0)
+ elif self.config.span_frames_min_duration == timedelta(seconds=0):
+ return timedelta(seconds=-1)
+ else:
+ return self.config.span_frames_min_duration
 
  def begin_transaction(self, transaction_type, trace_parent=None, start=None, auto_activate=True):
  """

tests/client/transaction_tests.py

@@ -223,8 +223,8 @@ def test_transaction_max_spans_dynamic(elasticapm_client):
  assert len(spans) == 3
 
 
-@pytest.mark.parametrize("elasticapm_client", [{"span_frames_min_duration": 20}], indirect=True)
-def test_transaction_span_frames_min_duration(elasticapm_client):
+@pytest.mark.parametrize("elasticapm_client", [{"span_stack_trace_min_duration": 20}], indirect=True)
+def test_transaction_span_stack_trace_min_duration(elasticapm_client):
  elasticapm_client.begin_transaction("test_type")
  with elasticapm.capture_span("noframes", duration=0.001):
  pass
@@ -242,8 +242,8 @@ def test_transaction_span_frames_min_duration(elasticapm_client):
  assert spans[1]["stacktrace"] is not None
 
 
-@pytest.mark.parametrize("elasticapm_client", [{"span_frames_min_durarion_ms": -1}], indirect=True)
-def test_transaction_span_frames_min_duration_no_limit(elasticapm_client):
+@pytest.mark.parametrize("elasticapm_client", [{"span_stack_trace_min_duration": 0}], indirect=True)
+def test_transaction_span_stack_trace_min_duration_no_limit(elasticapm_client):
  elasticapm_client.begin_transaction("test_type")
  with elasticapm.capture_span("frames"):
  pass
@@ -261,8 +261,8 @@ def test_transaction_span_frames_min_duration_no_limit(elasticapm_client):
  assert spans[1]["stacktrace"] is not None
 
 
-def test_transaction_span_frames_min_duration_dynamic(elasticapm_client):
- elasticapm_client.config.update(version="1", span_frames_min_duration=20)
+def test_transaction_span_stack_trace_min_duration_dynamic(elasticapm_client):
+ elasticapm_client.config.update(version="1", span_stack_trace_min_duration=20)
  elasticapm_client.begin_transaction("test_type")
  with elasticapm.capture_span("noframes", duration=0.001):
  pass
@@ -279,7 +279,7 @@ def test_transaction_span_frames_min_duration_dynamic(elasticapm_client):
  assert spans[1]["name"] == "frames"
  assert spans[1]["stacktrace"] is not None
 
- elasticapm_client.config.update(version="1", span_frames_min_duration=-1)
+ elasticapm_client.config.update(version="1", span_stack_trace_min_duration=0)
  elasticapm_client.begin_transaction("test_type")
  with elasticapm.capture_span("frames"):
  pass
@@ -297,6 +297,46 @@ def test_transaction_span_frames_min_duration_dynamic(elasticapm_client):
  assert spans[3]["stacktrace"] is not None
 
 
+def test_transaction_span_stack_trace_min_duration_overrides_old_config(elasticapm_client):
+ """
+ span_stack_trace_min_duration overrides span_frames_min_duration (which is deprecated)
+ """
+ elasticapm_client.config.update(version="1", span_stack_trace_min_duration=20, span_frames_min_duration=1)
+ elasticapm_client.begin_transaction("test_type")
+ with elasticapm.capture_span("noframes", duration=0.01):
+ pass
+ with elasticapm.capture_span("frames", duration=0.04):
+ pass
+ elasticapm_client.end_transaction("test")
+
+ spans = elasticapm_client.events[constants.SPAN]
+
+ assert len(spans) == 2
+ assert spans[0]["name"] == "noframes"
+ assert "stacktrace" not in spans[0]
+
+ assert spans[1]["name"] == "frames"
+ assert spans[1]["stacktrace"] is not None
+
+ # Set span_stack_trace_min_duration to default so it picks up the non-default span_frames_min_duration
+ elasticapm_client.config.update(version="1", span_stack_trace_min_duration=5, span_frames_min_duration=1)
+ elasticapm_client.begin_transaction("test_type")
+ with elasticapm.capture_span("yesframes", duration=0.01):
+ pass
+ with elasticapm.capture_span("frames", duration=0.04):
+ pass
+ elasticapm_client.end_transaction("test")
+
+ spans = elasticapm_client.events[constants.SPAN]
+
+ assert len(spans) == 4
+ assert spans[2]["name"] == "yesframes"
+ assert spans[2]["stacktrace"] is not None
+
+ assert spans[3]["name"] == "frames"
+ assert spans[3]["stacktrace"] is not None
+
+
 def test_transaction_keyword_truncation(elasticapm_client):
  too_long = "x" * (constants.KEYWORD_MAX_LENGTH + 1)
  expected = encoding.keyword_field(too_long)

tests/contrib/django/fixtures.py

@@ -56,7 +56,7 @@ 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", -1)
+ client_config.setdefault("span_stack_trace_min_duration", 0)
  client_config.setdefault("span_compression_exact_match_max_duration", "0ms")
  client_config.setdefault("span_compression_same_kind_max_duration", "0ms")
  app = apps.get_app_config("elasticapm")
@@ -85,7 +85,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", -1)
+ client_config.setdefault("span_stack_trace_min_duration", 0)
  client_config.setdefault("span_compression_exact_match_max_duration", "0ms")
  client_config.setdefault("span_compression_same_kind_max_duration", "0ms")
  client_config.setdefault("exit_span_min_duration", "0ms")

tests/fixtures.py

@@ -186,7 +186,7 @@ def elasticapm_client(request):
  client_config.setdefault("secret_token", "test_key")
  client_config.setdefault("central_config", "false")
  client_config.setdefault("include_paths", ("*/tests/*",))
- client_config.setdefault("span_frames_min_duration", -1)
+ client_config.setdefault("span_stack_trace_min_duration", 0)
  client_config.setdefault("metrics_interval", "0ms")
  client_config.setdefault("cloud_provider", False)
  client_config.setdefault("span_compression_exact_match_max_duration", "0ms")
@@ -220,7 +220,7 @@ def elasticapm_client_log_file(request):
  client_config.setdefault("secret_token", "test_key")
  client_config.setdefault("central_config", "false")
  client_config.setdefault("include_paths", ("*/tests/*",))
- client_config.setdefault("span_frames_min_duration", -1)
+ client_config.setdefault("span_stack_trace_min_duration", 0)
  client_config.setdefault("span_compression_exact_match_max_duration", "0ms")
  client_config.setdefault("span_compression_same_kind_max_duration", "0ms")
  client_config.setdefault("metrics_interval", "0ms")
@@ -303,7 +303,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", -1)
+ client_config.setdefault("span_stack_trace_min_duration", 0)
  client_config.setdefault("span_compression_exact_match_max_duration", "0ms")
  client_config.setdefault("span_compression_same_kind_max_duration", "0ms")
  client_config.setdefault("include_paths", ("*/tests/*",))

tests/utils/stacks/tests.py

@@ -144,7 +144,7 @@ def test_iter_stack_frames_max_frames():
 
 
 @pytest.mark.parametrize(
- "elasticapm_client", [{"stack_trace_limit": 10, "span_frames_min_duration": -1}], indirect=True
+ "elasticapm_client", [{"stack_trace_limit": 10, "span_stack_trace_min_duration": 0}], indirect=True
 )
 def test_iter_stack_frames_max_frames_is_dynamic(elasticapm_client):
  def func():