Skip to content

[Bug]: Performance: InstanaSpan.__init__ shares one mutable default events list across every span - resulting in unbounded CPU / memory growth #896

Description

@mpawlow

Problem Description

Metadata

  • Affected version: 3.17.0 (current release at time of writing)
  • Severity: High — unbounded memory growth, unbounded CPU growth, and cross-trace data leakage in exported spans
  • Component: instana/span/span.py, instana/span/readable_span.py

Affected Team

  • IBM OpenRAG in watsonx.data
  • 👉 I'm willing to contribute a PR (if help wanted)

Summary

InstanaSpan.__init__ declares its events parameter with a mutable default:

# instana/span/span.py:45-57
def __init__(
    self,
    name: str,
    context: SpanContext,
    span_processor: StanRecorder,
    parent_id: Optional[str] = None,
    start_time: Optional[int] = None,
    end_time: Optional[int] = None,
    attributes: types.Attributes = {},
    events: Sequence[Event] = [],          # <-- evaluated once, at def time
    status: Optional[Status] = Status(StatusCode.UNSET),
    kind: SpanKind = SpanKind.INTERNAL,
) -> None:

The value is passed straight through to ReadableSpan, which stores the caller's object by reference rather than copying it:

# instana/span/readable_span.py:71-72
self._attributes = attributes if attributes else {}
self._events = events                     # <-- no copy

Note the asymmetry on those two adjacent lines: attributes is protected by if attributes else {}, which happens to substitute a fresh dict for the shared default. events has no such guard.

Neither of the two places the tracer constructs an InstanaSpaninstana/tracer.py:127 and instana/instrumentation/asyncio.py:75 — passes events=. So every InstanaSpan created in the process shares one single list object: the one bound to InstanaSpan.__init__.__defaults__. add_event then appends into it:

# instana/span/span.py:122-134
def add_event(self, name, attributes=None, timestamp=None) -> None:
    event = Event(name=name, attributes=attributes, timestamp=timestamp)
    self._events.append(event)            # <-- appends to the shared list

Nothing ever removes an entry. The list is process-global, is never cleared, and is not scoped to a span, a trace, or a request.

There are two callers of add_event in the tracer, and both are on ordinary hot paths:

Caller Fires on
instana/instrumentation/logging.py:68 every WARNING/ERROR logged while a trace is active
instana/span/span.py:177 (record_exception) every exception recorded on a span whose name has no dedicated error attribute

Impact

1. Unbounded memory growth

Every Event ever created stays reachable for the lifetime of the process. For a long-running web service that logs warnings under load, this is a straightforward memory leak that grows without limit.

2. Unbounded CPU growth (O(n) per event, O(n²) cumulative)

Two consumers iterate the whole list every time a span is serialised:

# instana/span/registered_span.py:470-478
def _collect_log_attributes(self, span: "InstanaSpan") -> None:
    # use last special key values
    for event in span.events:             # <-- walks every event in the process
        if "message" in event.attributes:
            self.data["log"]["message"] = event.attributes.pop("message", None)
        ...
# instana/span/sdk_span.py:29-35
if span.events is not None and len(span.events) > 0:
    events = DictionaryOfStan()
    for event in span.events:             # <-- same
        filtered_attributes = self._validate_attributes(event.attributes)
        if len(filtered_attributes.keys()) > 0:
            events[repr(event.timestamp)] = filtered_attributes
    self.data["sdk"]["custom"]["events"] = events

So the cost of recording the n-th log span is proportional to n. In the application where we found this, a single in-trace log.warning() cost 10.9 µs untraced vs ~1010 µs traced, and the traced figure kept climbing as the list grew.

3. Cross-trace data leakage in exported spans (most serious)

SDKSpan.__init__ serialises the entire shared list into the payload of every SDK span. An exception recorded once, on one span, in one trace, is therefore re-exported attached to every unrelated SDK span produced afterwards, for as long as the process lives.

This is not merely noisy: exception messages routinely contain user identifiers, record IDs, and other request-specific data. Attaching them to unrelated spans misattributes that data to traces, endpoints, and (in a multi-tenant service) potentially to users that had nothing to do with it. See the second reproducer below for a demonstration.

Log events happen to escape the content half of this problem by accident: _collect_log_attributes pops message/parameters out of event.attributes, so by the time a later SDKSpan serialises them their attributes are empty and the len(filtered_attributes.keys()) > 0 guard skips them. They still leak memory and still cost O(n) to walk. Exception events are never popped, so they leak in full.

Suggested fix

The standard Python remedy — None sentinel plus a per-instance list — applied at both levels. ReadableSpan must copy rather than alias, since InstanaSpan._readable_span() passes events=self.events and the readable span outlives the mutable one:

--- a/instana/span/span.py
+++ b/instana/span/span.py
@@ class InstanaSpan
-        attributes: types.Attributes = {},
-        events: Sequence[Event] = [],
+        attributes: Optional[types.Attributes] = None,
+        events: Optional[Sequence[Event]] = None,
--- a/instana/span/readable_span.py
+++ b/instana/span/readable_span.py
@@ class ReadableSpan.__init__
-        attributes: types.Attributes = {},
-        events: Sequence[Event] = [],
+        attributes: Optional[types.Attributes] = None,
+        events: Optional[Sequence[Event]] = None,
@@
         self._attributes = attributes if attributes else {}
-        self._events = events
+        self._events = list(events) if events else []

ReadableSpan.__init__ carries the same mutable-default hazard on its own events parameter (readable_span.py:57), so it is worth fixing there in the same change even though the aliasing in InstanaSpan is what makes it reachable today.

Worth auditing at the same time: attributes: types.Attributes = {} on both classes is the same anti-pattern. It is currently harmless only because of the if attributes else {} guard, which silently substitutes a fresh dict — a guard that a future refactor could remove without any test noticing.

Suggested regression test

def test_spans_do_not_share_an_events_list():
    a = tracer.start_span("a")
    b = tracer.start_span("b")
    a.add_event(name="only-on-a", attributes={"message": "x"})
    assert len(b.events) == 0
    assert a.events is not b.events

Workaround for affected users

Until a fix ships, INSTANA_TRACING_DISABLE=logging suppresses logging spans and removes the dominant source of leaked events. Measured on the same application: an in-trace warning drops from ~1010 µs to ~26 µs, live Event objects stay at 0, and the per-warning cost stays flat instead of climbing.

This does not address record_exception, which is not gated by that setting — any recorded exception still leaks and still contaminates later SDK spans.

Notes on how this surfaces in production

We found this while investigating a backend that felt progressively slower with APM enabled. The characteristic signature, if it helps others match the symptom:

  • Latency degrades gradually over a process's lifetime rather than jumping at deploy, and a restart resets it.
  • The regression tracks warning/error log volume, not request volume, so it is worst during incidents — exactly when the tracing data matters most.
  • RSS climbs steadily and never plateaus.
  • Time is spent on the request thread, not in the reporting thread, so it appears as application latency rather than as tracer overhead.

One adjacent (separate) issue we hit while measuring, mentioned only in case it is useful context: the default stack_trace_level = "all" (instana/options.py:59) means a full traceback.extract_stack() — including linecache source reads — on every EXIT span. Since EXIT_SPANS includes httpx, urllib3, sqlalchemy and log, that is a stack capture per outbound HTTP call, per database query, and per warning. We measured 127 µs at stack depth 30, 221 µs at depth 60 and 355 µs at depth 100; async web frameworks sit at the deep end of that range. INSTANA_STACK_TRACE=error avoids it. That is a defensible default rather than a bug, but the combination with the leak above is what made the slowdown so pronounced.

Minimal, Complete, Verifiable, Example

Steps to reproduce

Reproducer 1 — the leak itself

No Instana agent is required to observe the memory leak. Save as repro.py:

"""Reproducer for the shared-events leak in instana 3.17.0."""

import gc
import logging
import os
import time

os.environ.setdefault("INSTANA_AGENT_HOST", "127.0.0.1")
os.environ.setdefault("INSTANA_AGENT_PORT", "1")  # deliberately dead: no agent needed

import instana  # noqa: F401  — importing boots the tracer
from instana.singletons import get_tracer
from instana.span.readable_span import Event
from instana.span.span import InstanaSpan

log = logging.getLogger("repro")
log.setLevel(logging.INFO)
log.handlers[:] = [logging.NullHandler()]
log.propagate = False

# The shared list is the mutable default of InstanaSpan.__init__(events=[]).
shared = next(d for d in InstanaSpan.__init__.__defaults__ if isinstance(d, list))
print(f"shared default list: id={id(shared)} len={len(shared)}\n")

tracer = get_tracer()

for request in range(4):
    # Each iteration is an independent root span, i.e. a separate HTTP request.
    t0 = time.perf_counter()
    with tracer.start_as_current_span("sdk", attributes={"name": f"request-{request}"}):
        for _ in range(500):
            log.warning("a warning logged while handling a request")
    dt = (time.perf_counter() - t0) * 1e3 / 500

    live = sum(1 for o in gc.get_objects() if isinstance(o, Event))
    print(
        f"request {request}: {dt:7.3f} ms per warning | "
        f"shared list len={len(shared):5d} | live Event objects={live:5d}"
    )
pip install instana==3.17.0
python repro.py

Expected: each root span owns its own event list; the list is empty between requests; Event objects are freed with the span that created them; per-warning cost is flat.

Actual — no agent reachable (memory leak only):

shared default list: id=133376541986624 len=0

request 0:   0.367 ms per warning | shared list len=  500 | live Event objects=  500
request 1:   0.252 ms per warning | shared list len= 1000 | live Event objects= 1000
request 2:   0.255 ms per warning | shared list len= 1500 | live Event objects= 1500
request 3:   0.261 ms per warning | shared list len= 2000 | live Event objects= 2000

Actual — with a live agent on 42699 (leak plus the O(n) walk):

request 0:   0.457 ms per warning | shared list len=  500 | live Event objects=  500
request 1:   0.407 ms per warning | shared list len= 1000 | live Event objects= 1000
request 2:   0.483 ms per warning | shared list len= 1500 | live Event objects= 1500
request 3:   0.594 ms per warning | shared list len= 2000 | live Event objects= 2000

The list grows by exactly the number of warnings logged, never shrinks, and keeps the same object id across independent root spans. The per-warning cost rises only when an agent is connected, because StanRecorder.record_span returns early when agent.can_send() is False and the O(n) walk in _collect_log_attributes is never reached.

Reproducer 2 — cross-trace contamination of exported spans

This one does need a reachable agent, since record_span returns early otherwise. Save as contaminate.py:

"""One recorded exception is re-exported on every later SDK span."""

import logging
import os
import time

os.environ.setdefault("INSTANA_AGENT_HOST", "127.0.0.1")
os.environ.setdefault("INSTANA_AGENT_PORT", "42699")

import instana  # noqa: F401
from instana.singletons import agent, get_tracer

logging.getLogger().addHandler(logging.NullHandler())

tracer = get_tracer()

# Capture what the tracer hands to the reporter, before the collector thread
# drains the queue on its 1s cycle.
_CAPTURED = []
_orig_put = agent.collector.span_queue.put


def _capture(json_span, *a, **kw):
    _CAPTURED.append(json_span)
    return _orig_put(json_span, *a, **kw)


agent.collector.span_queue.put = _capture

# Wait for the agent handshake, otherwise record_span() returns early.
for _ in range(100):
    if agent.can_send():
        break
    time.sleep(0.1)
print("agent ready:", agent.can_send())

# Request 1: a custom span records an exception carrying request-specific text.
with tracer.start_as_current_span("checkout", attributes={"name": "request-1"}) as span:
    span.record_exception(ValueError("card declined for customer alice@example.com"))

# Requests 2..4: unrelated custom spans. They record nothing at all.
for i in range(2, 5):
    with tracer.start_as_current_span("healthcheck", attributes={"name": f"request-{i}"}):
        pass

for s in _CAPTURED:
    sdk = s.data.get("sdk", {})
    label = sdk.get("custom", {}).get("tags", {}).get("name", sdk.get("name"))
    events = sdk.get("custom", {}).get("events", {})
    print(f"span {sdk.get('name')!r} ({label}): {len(events)} event(s)")
    for _ts, attrs in events.items():
        print(f"    -> {dict(attrs)}")

Expected: the exception appears on checkout / request-1 only. The three healthcheck spans carry no events.

Actual:

agent ready: True
span 'checkout' (request-1): 1 event(s)
    -> {'message': 'card declined for customer alice@example.com'}
span 'healthcheck' (request-2): 1 event(s)
    -> {'message': 'card declined for customer alice@example.com'}
span 'healthcheck' (request-3): 1 event(s)
    -> {'message': 'card declined for customer alice@example.com'}
span 'healthcheck' (request-4): 1 event(s)
    -> {'message': 'card declined for customer alice@example.com'}

Every subsequent SDK span in the process carries that exception message, and would continue to as more spans are produced.

Python Version

Python 3.13.14

Python Modules

sudo apt list '*python*' --installed



Listing... Done
libpython3-stdlib/noble-updates,noble-security,now 3.12.3-0ubuntu2.1 amd64 [installed,automatic]
libpython3.12-dev/noble-updates,noble-security,now 3.12.3-1ubuntu0.15 amd64 [installed,automatic]
libpython3.12-minimal/noble-updates,noble-security,now 3.12.3-1ubuntu0.15 amd64 [installed,automatic]
libpython3.12-stdlib/noble-updates,noble-security,now 3.12.3-1ubuntu0.15 amd64 [installed,automatic]
libpython3.12t64/noble-updates,noble-security,now 3.12.3-1ubuntu0.15 amd64 [installed,automatic]
libpython3.13-dev/now 3.13.14-1+noble1 amd64 [installed,upgradable to: 3.13.15-1+noble1]
libpython3.13-stdlib/now 3.13.14-1+noble1 amd64 [installed,upgradable to: 3.13.15-1+noble1]
libpython3.13/now 3.13.14-1+noble1 amd64 [installed,upgradable to: 3.13.15-1+noble1]
python-apt-common/noble-updates,now 2.7.7ubuntu5.2 all [installed,automatic]
python-babel-localedata/noble,now 2.10.3-3build1 all [installed,automatic]
python3-apport/noble-security,now 2.28.1-0ubuntu3.8 all [installed,upgradable to: 2.28.3-0ubuntu0.1]
python3-apt/noble-updates,now 2.7.7ubuntu5.2 amd64 [installed,automatic]
python3-attr/noble,now 23.2.0-2 all [installed,automatic]
python3-automat/noble,now 22.10.0-2 all [installed,automatic]
python3-babel/noble,now 2.10.3-3build1 all [installed,automatic]
python3-bcrypt/noble,now 3.2.2-1build1 amd64 [installed,automatic]
python3-blinker/noble,now 1.7.0-1 all [installed,automatic]
python3-boto3/noble,now 1.34.46+dfsg-1ubuntu1 all [installed,automatic]
python3-botocore/noble,now 1.34.46+repack-1ubuntu1 all [installed,automatic]
python3-bpfcc/noble,now 0.29.1+ds-1ubuntu7 all [installed,automatic]
python3-certifi/noble,now 2023.11.17-1 all [installed,automatic]
python3-cffi-backend/noble,now 1.16.0-2build1 amd64 [installed,automatic]
python3-chardet/noble,now 5.2.0+dfsg-1 all [installed,automatic]
python3-click/noble,now 8.1.6-2 all [installed,automatic]
python3-colorama/noble,now 0.4.6-4 all [installed,automatic]
python3-commandnotfound/noble,now 23.04.0 all [installed,automatic]
python3-configobj/noble,now 5.0.8-3 all [installed,automatic]
python3-constantly/noble,now 23.10.4-1 all [installed,automatic]
python3-cryptography/noble-updates,noble-security,now 41.0.7-4ubuntu0.4 amd64 [installed,automatic]
python3-dateutil/noble,now 2.8.2-3ubuntu1 all [installed,automatic]
python3-dbus/noble,now 1.3.2-5build3 amd64 [installed,automatic]
python3-debconf/noble,now 1.5.86ubuntu1 all [installed,automatic]
python3-debian/noble,now 0.1.49ubuntu2 all [installed,automatic]
python3-distro-info/noble,now 1.7build1 all [installed,automatic]
python3-distro/noble,now 1.9.0-1 all [installed,automatic]
python3-distupgrade/noble-updates,now 1:24.04.28 all [installed,automatic]
python3-gdbm/noble,now 3.12.3-0ubuntu1 amd64 [installed,automatic]
python3-gi/noble,now 3.48.2-1 amd64 [installed,automatic]
python3-hamcrest/noble,now 2.1.0-1 all [installed,automatic]
python3-httplib2/noble-updates,noble-security,now 0.20.4-3ubuntu0.1 all [installed,automatic]
python3-hyperlink/noble,now 21.0.0-5 all [installed,automatic]
python3-idna/noble-updates,noble-security,now 3.6-2ubuntu0.2 all [installed,automatic]
python3-incremental/noble,now 22.10.0-1 all [installed,automatic]
python3-jinja2/noble-updates,noble-security,now 3.1.2-1ubuntu1.3 all [installed,automatic]
python3-jmespath/noble,now 1.0.1-1 all [installed,automatic]
python3-json-pointer/noble,now 2.0-0ubuntu1 all [installed,automatic]
python3-jsonpatch/noble,now 1.32-3 all [installed,automatic]
python3-jsonschema/noble,now 4.10.3-2ubuntu1 all [installed,automatic]
python3-jwt/noble-updates,noble-security,now 2.7.0-1ubuntu0.1 all [installed,automatic]
python3-launchpadlib/noble,now 1.11.0-6 all [installed,automatic]
python3-lazr.restfulclient/noble,now 0.14.6-1 all [installed,automatic]
python3-lazr.uri/noble,now 1.0.6-3 all [installed,automatic]
python3-magic/noble,now 2:0.4.27-3 all [installed,automatic]
python3-markdown-it/noble,now 3.0.0-2 all [installed,automatic]
python3-markupsafe/noble,now 2.1.5-1build2 amd64 [installed,automatic]
python3-mdurl/noble,now 0.1.2-1 all [installed,automatic]
python3-minimal/noble-updates,noble-security,now 3.12.3-0ubuntu2.1 amd64 [installed,automatic]
python3-netaddr/noble,now 0.8.0-2ubuntu1 all [installed,automatic]
python3-netifaces/noble,now 0.11.0-2build3 amd64 [installed,automatic]
python3-netplan/noble-updates,now 1.1.2-8ubuntu1~24.04.2 amd64 [installed,automatic]
python3-newt/noble,now 0.52.24-2ubuntu2 amd64 [installed,automatic]
python3-oauthlib/noble,now 3.2.2-1 all [installed,automatic]
python3-openssl/noble-updates,noble-security,now 23.2.0-1ubuntu0.1 all [installed,automatic]
python3-packaging/noble,now 24.0-1 all [installed,automatic]
python3-pexpect/noble,now 4.9-2 all [installed,automatic]
python3-pkg-resources/noble-updates,noble-security,now 68.1.2-2ubuntu1.2 all [installed,automatic]
python3-problem-report/noble-security,now 2.28.1-0ubuntu3.8 all [installed,upgradable to: 2.28.3-0ubuntu0.1]
python3-ptyprocess/noble,now 0.7.0-5 all [installed,automatic]
python3-pyasn1-modules/noble,now 0.2.8-1 all [installed,automatic]
python3-pyasn1/noble-updates,noble-security,now 0.4.8-4ubuntu0.2 all [installed,automatic]
python3-pygments/noble,now 2.17.2+dfsg-1 all [installed,automatic]
python3-pyparsing/noble,now 3.1.1-1 all [installed,automatic]
python3-pyrsistent/noble,now 0.20.0-1build2 amd64 [installed,automatic]
python3-requests/noble-updates,noble-security,now 2.31.0+dfsg-1ubuntu1.1 all [installed,automatic]
python3-rich/noble,now 13.7.1-1 all [installed,automatic]
python3-s3transfer/noble,now 0.10.1-1ubuntu2 all [installed,automatic]
python3-serial/noble,now 3.5-2 all [installed,automatic]
python3-service-identity/noble,now 24.1.0-1 all [installed,automatic]
python3-setuptools/noble-updates,noble-security,now 68.1.2-2ubuntu1.2 all [installed,automatic]
python3-six/noble,now 1.16.0-4 all [installed,automatic]
python3-software-properties/noble-updates,now 0.99.49.4 all [installed,automatic]
python3-systemd/noble,now 235-1build4 amd64 [installed,automatic]
python3-twisted/noble-updates,noble-security,now 24.3.0-1ubuntu0.2 all [installed,automatic]
python3-tz/noble,now 2024.1-2 all [installed,automatic]
python3-update-manager/noble-updates,now 1:24.04.12 all [installed,automatic]
python3-urllib3/noble-updates,noble-security,now 2.0.7-1ubuntu0.7 all [installed,automatic]
python3-wadllib/noble,now 1.3.6-5 all [installed,automatic]
python3-xkit/noble,now 0.5.0ubuntu6 all [installed,automatic]
python3-yaml/noble,now 6.0.1-2build2 amd64 [installed,automatic]
python3-zope.interface/noble,now 6.1-1build1 amd64 [installed,automatic]
python3.12-dev/noble-updates,noble-security,now 3.12.3-1ubuntu0.15 amd64 [installed]
python3.12-minimal/noble-updates,noble-security,now 3.12.3-1ubuntu0.15 amd64 [installed,automatic]
python3.12/noble-updates,noble-security,now 3.12.3-1ubuntu0.15 amd64 [installed,automatic]
python3.13-dev/now 3.13.14-1+noble1 amd64 [installed,upgradable to: 3.13.15-1+noble1]
python3.13-venv/now 3.13.14-1+noble1 amd64 [installed,upgradable to: 3.13.15-1+noble1]
python3.13/now 3.13.14-1+noble1 amd64 [installed,upgradable to: 3.13.15-1+noble1]
python3/noble-updates,noble-security,now 3.12.3-0ubuntu2.1 amd64 [installed,automatic]

Python Environment

instana 3.17.0 (latest release; verified the mutable default is present in a clean install from PyPI)
Python 3.13.14 (CPython, GCC 13.3.0)
opentelemetry-api 1.44.0
OS Linux 6.8.0-138-generic, x86_64, glibc 2.39
Agent icr.io/instana/agent:1.323.1 (host agent, for the reproducers that need one)
Application Python 3.13 / FastAPI / uvicorn service, single worker, auto-instrumented via import instana

Metadata

Metadata

Assignees

No one assigned

    Labels

    Type

    No type

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions