Skip to content
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
125 changes: 71 additions & 54 deletions benchmarks/README.md
Original file line number Diff line number Diff line change
Expand Up @@ -3,15 +3,15 @@
## 1. The short answer

On a do-nothing endpoint through uvicorn, the full stack costs **70% of throughput**
(7978 → 2389 RPS). Roughly half of that is recoverable without giving up observability, and
(7698 → 2313 RPS). Roughly a third of that is recoverable without giving up observability, and
**OpenTelemetry costs twice what Sentry does** - not the ordering most people expect.

Two published figures about the Sentry half look contradictory and are both correct.
[getsentry/sentry-python#2116](https://github.com/getsentry/sentry-python/issues/2116), open
since 2023, reports a Starlette app dropping from ~2000 to ~1000 RPS after adding the SDK;
Sentry's own docs claim
[under 1 ms of instrumentation overhead per request](https://docs.sentry.io/product/insights/performance-overhead/).
Both hold at once, because the added cost is a fixed ~80 µs: small in absolute terms, and
Both hold at once, because the added cost is a fixed ~70 µs: small in absolute terms, and
enormous next to a handler that does nothing.

That is also the caveat on everything below. These ratios are an upper bound. A service that
Expand All @@ -28,7 +28,7 @@ instruments, configured through `FastAPIBootstrapper`) - measured three ways:
baseline is unrealistically fast.
- **Real server** (`run_http.py`) - uvicorn, single worker, access log off, loaded with
`ab -k -c 16 -n 20000`. Verified the load generator is not the ceiling (baseline plateaus at
~8.7k RPS by c=64, vs 7.9k measured at c=16).
~8.4k RPS by c=64, vs 7.7k measured at c=16).
- **Micro** (`micro.py`, `verify.py`, `profile_one.py`) - per-operation costs, what each
configuration actually gives up, and cProfile.

Expand All @@ -47,52 +47,58 @@ structlog 26.1.0. Endpoint: `async def` returning `{"ok": True}`. Median of 5 ro

## 3. Headline numbers

<!-- --8<-- [start:headline] -->
Real server, uvicorn + `ab -k`, trivial async endpoint:

| config | RPS | µs/req | vs bare |
|---|---:|---:|---|
| bare FastAPI | 7978 | 125.3 | - |
| full lite-bootstrap stack (otel + prometheus + structlog + sentry) | 2389 | 418.6 | **−70%** |
| same stack, tuned (§6) | 4187 | 238.8 | −48% |
| bare FastAPI | 7698 | 129.9 | - |
| full lite-bootstrap stack (otel + prometheus + structlog + sentry) | 2313 | 432.3 | **−70%** |
| same stack, tuned (§6) | 4164 | 240.2 | −46% |

Same endpoint plus three structlog records per request:

| config | RPS | µs/req | vs bare |
|---|---:|---:|---|
| bare | 5716 | 175.0 | - |
| full stack | 2013 | 496.7 | **−65%** |
| tuned | 3476 | 287.7 | −39% |
| bare | 5548 | 180.3 | - |
| full stack | 1944 | 514.5 | **−65%** |
| tuned | 3418 | 292.5 | −38% |

In-process (SDK cost isolated, baseline 16.2 µs/req): full stack 61628 → 4268 RPS, **14.5x**.
Tuned recovers it to 9150, **2.14x** over the untuned stack.
<!-- --8<-- [end:headline] -->

The tuning is worth **+75% RPS** on the real server, and in-process the untuned stack costs an
In-process (SDK cost isolated, baseline 16.2 µs/req): full stack 61667 → 4056 RPS, **15.2x**.
Tuned recovers it to 9061, **2.23x** over the untuned stack.

The tuning is worth **+80% RPS** on the real server, and in-process the untuned stack costs an
order of magnitude of a do-nothing handler's throughput.

## 4. Per-instrument breakdown

In-process, each instrument alone, baseline 15.8 µs/req:
In-process, each instrument alone, baseline 16.2 µs/req:

<!-- --8<-- [start:perinstrument] -->
| instrument | RPS | +µs/req | share of full stack |
|---|---:|---:|---|
| `LoggingInstrument` (configured, no logs emitted) | 62680 | +0.1 | ~0% |
| `PrometheusInstrument` | 29983 | +17.5 | 8% |
| `SentryInstrument` (tracing off) | 13449 | +58.5 | 27% |
| `OpenTelemetryInstrument` | 7356 | **+120.1** | 55% |
| all four | 4293 | +217.1 | |

Costs are close to additive (0.1 + 17.5 + 58.5 + 120.1 = 196 vs 217 measured). **OpenTelemetry is
| `LoggingInstrument` (configured, no logs emitted) | 61133 | +0.1 | ~0% |
| `PrometheusInstrument` | 29470 | +17.7 | 8% |
| `SentryInstrument` (tracing off) | 13541 | +57.6 | 25% |
| `OpenTelemetryInstrument` | 7280 | **+121.1** | 53% |
| all four | 4056 | +230.3 | |
<!-- --8<-- [end:perinstrument] -->

Costs are roughly additive, with the combination 17% dearer than the parts
(0.1 + 17.7 + 57.6 + 121.1 = 196 vs 230 measured). **OpenTelemetry is
twice Sentry**, which was not the expected ordering, and structlog's instrument costs nothing
until you actually log.

### 4a. OpenTelemetry: the two knobs that pay

| scenario | RPS | µs/req | gain |
|---|---:|---:|---|
| `otel` as lite-bootstrap configures it | 7375 | 135.6 | - |
| `+ exclude_spans=["receive", "send"]` | 9755 | 102.5 | −33.1 µs |
| `+ ParentBased(TraceIdRatioBased(0.01))` sampler | 12484 | 80.1 | −55.5 µs |
| both | 15922 | 62.8 | **2.16x** |
| `otel` as lite-bootstrap configures it | 7267 | 137.6 | - |
| `+ opentelemetry_exclude_spans=["receive", "send"]` | 9651 | 103.6 | −34.0 µs |
| `+ opentelemetry_sampler=ParentBased(TraceIdRatioBased(0.01))` | 12154 | 82.3 | −55.3 µs |
| both | 15518 | 64.4 | **2.14x** |

1. `FastAPIInstrumentor.instrument_app` accepts `exclude_spans: list[Literal["receive","send"]]`,
which `FastAPIConfig.opentelemetry_exclude_spans` passes through. It is empty by default, so
Expand All @@ -106,19 +112,21 @@ until you actually log.

### 4b. Sentry: the cost is one thing, and it is not the one people tune

In-process ablation, Sentry only, baseline 15.6 µs/req:
In-process ablation, Sentry only, baseline 16.5 µs/req:

<!-- --8<-- [start:sentryablation] -->
| scenario | +µs | reading |
|---|---:|---|
| defaults (tracing off) | +61.3 | the number to beat |
| `attach_stacktrace=False` | +61.5 | no effect on the happy path |
| `max_breadcrumbs=0` | +62.0 | no effect - the crumb is still built |
| `disabled_integrations=[Stdlib, Modules, Dedupe, Excepthook, Threading]` | +61.4 | no effect |
| `default_integrations=False` (Starlette+FastAPI kept) | +61.9 | no effect |
| **`integrations=[]`, no framework integration** | **+0.4** | **all of it is the ASGI integration** |
| `auto_session_tracking=False` | +54.4 | sessions cost ~7 µs |
| `http_methods_to_capture=()` (no Transaction) | +27.2 | the Transaction costs ~34 µs |
| both of the above | +19.2 | |
| defaults (tracing off) | +64.2 | the number to beat |
| `attach_stacktrace=False` | +63.2 | no effect on the happy path |
| `max_breadcrumbs=0` | +63.4 | no effect - the crumb is still built |
| `disabled_integrations=[Stdlib, Modules, Dedupe, Excepthook, Threading]` | +63.8 | no effect |
| `default_integrations=False` (Starlette+FastAPI kept) | +63.8 | no effect |
| **`integrations=[]`, no framework integration** | **−0.1** | **all of it is the ASGI integration** |
| `auto_session_tracking=False` | +56.5 | sessions cost ~7.7 µs |
| `http_methods_to_capture=()` (no Transaction) | +29.2 | the Transaction costs ~35 µs |
| both of the above | +19.9 | |
<!-- --8<-- [end:sentryablation] -->

The first block is the useful negative result: **every knob people reach for first buys nothing.**
All the cost is in `SentryAsgiMiddleware._run_app`, and most of it is a `Transaction` built and
Expand All @@ -128,37 +136,41 @@ Micro-benchmarks (`micro.py`):

| operation | µs |
|---|---:|
| `Random(trace_id)` - seeding Mersenne Twister | 6.42 |
| `_generate_sample_rand(trace_id)` | 6.99 |
| `Transaction(op, name, source)` | 9.63 |
| `scope.continue_trace(headers)` | 11.02 |
| `start_transaction(txn)` + exit, tracing **off** | 18.54 |
| `scope.generate_propagation_context(headers)` | 0.61 |
| `isolation_scope()` enter/exit | 2.25 |
| `Random(trace_id)` - seeding Mersenne Twister | 6.60 |
| `_generate_sample_rand(trace_id)` | 7.18 |
| `Transaction(op, name, source)` | 10.10 |
| `scope.continue_trace(headers)` | 11.28 |
| `start_transaction(txn)` + exit, tracing **off** | 19.25 |
| `scope.generate_propagation_context(headers)` | 0.64 |
| `isolation_scope()` enter/exit | 2.31 |
| `scope.fork()` | 0.62 |
| `get_client()` | 0.14 (×17 per request) |

`Transaction.__init__` unconditionally calls `_generate_sample_rand(self.trace_id)`, which does
`Random(trace_id)` - a full Mersenne Twister seed, 6.4 µs. It is 5.9 µs even for `Random(1)`, so
`Random(trace_id)` - a full Mersenne Twister seed, 6.6 µs. It is 6.1 µs even for `Random(1)`, so
the cost is the MT init, not the string hashing; deriving the same value arithmetically
(`int(trace_id, 16) / 2**128`) takes **0.23 µs, 27x cheaper**. This runs on every request even
(`int(trace_id, 16) / 2**128`) takes **0.25 µs, 27x cheaper**. This runs on every request even
when `traces_sample_rate is None`.

With `traces_sample_rate=1.0` the SDK costs +274 µs/req on the real server (2486 RPS, −68%).
With `traces_sample_rate=1.0` the SDK costs +353 µs/req on the real server: 1948 RPS against
this suite's own baseline of 6241, −69%. That baseline is Sentry-off on the same app, not §3's
bare FastAPI, so the two tables are not directly comparable.

### 4c. Logging: cost per record, not per request

Three records per request, in-process:

| scenario | +µs/req | delta |
|---|---:|---:|
| Sentry defaults | +99.7 | |
| `LoggingIntegration(sentry_logs_level=None)` | +92.9 | −1.9 µs/record |
| `LoggingIntegration(level=None, sentry_logs_level=None)` | +73.3 | −8.4 µs/record total |
| sentry-sdk defaults | +101.1 | |
| `sentry_logs_level=None` (lite-bootstrap's default since #186) | +93.8 | −2.4 µs/record |
| also `sentry_logging_breadcrumb_level=None` | +72.4 | −9.6 µs/record total |

Two handlers run per log record. `SentryLogsHandler.emit` calls `self.format(record)` *before* it
checks `has_logs_enabled(client.options)`, so with Sentry Logs disabled (the default, and
lite-bootstrap never sets `enable_logs`) every record is formatted an extra time for nothing.
lite-bootstrap passes `sentry_logs_level=None` by default, so a service gets the second row
without configuring anything.
`BreadcrumbHandler` then formats it again and builds a breadcrumb dict. `max_breadcrumbs=0` does
not help: the crumb is constructed before the deque drops it.

Expand All @@ -171,12 +183,14 @@ This hits lite-bootstrap directly because `LoggingInstrument` wires structlog th
Measured by capturing a real error event with an incoming `sentry-trace` header and inspecting the
envelope (`verify.py`):

<!-- --8<-- [start:tradeoffs] -->
| config | txn name | continues incoming trace | breadcrumbs |
|---|---|---|---|
| defaults | `/ping` | yes | yes |
| `http_methods_to_capture=()` | `/ping` | **no** | yes |
| `LoggingIntegration(level=None)` | `/ping` | yes | **no** |
| `sentry_logging_breadcrumb_level=None` | `/ping` | yes | **no** |
| propagation kept, Transaction skipped (patched SDK) | `/ping` | yes | yes |
<!-- --8<-- [end:tradeoffs] -->

`http_methods_to_capture=()` is not free: the error event gets a fresh `trace_id` and no
`parent_span_id`, which breaks cross-service correlation of errors in Sentry. Acceptable when
Expand All @@ -185,7 +199,7 @@ distributed tracing is OpenTelemetry's job - as it is in any lite-bootstrap serv

The last row is the interesting one: replacing `Scope.continue_trace` with a version that keeps
`generate_propagation_context(headers)` and returns no Transaction loses **nothing** on the error
event and still saves ~30 µs/req. That is a pure upstream bug, not a trade-off.
event and still saves ~32 µs/req. That is a pure upstream bug, not a trade-off.

Similarly, `opentelemetry_exclude_spans=["receive","send"]` costs you the ASGI event spans and
nothing else, and `sentry_logs_level=None` costs nothing at all while Sentry Logs is disabled -
Expand All @@ -195,6 +209,7 @@ which is why lite-bootstrap now applies it by default.

What "tuned" means in §3, all reachable through today's public API:

<!-- --8<-- [start:tuned] -->
```python
FastAPIConfig(
# Sentry: OTel owns distributed tracing, Sentry is an error sink
Expand All @@ -209,6 +224,7 @@ FastAPIConfig(
opentelemetry_sampler=ParentBased(TraceIdRatioBased(0.01)),
)
```
<!-- --8<-- [end:tuned] -->

Trade-offs, in order of what you give up: log breadcrumbs on Sentry errors, Sentry release health,
Sentry-side trace correlation, 99% of OTel traces, ASGI event spans.
Expand All @@ -230,12 +246,12 @@ lite-bootstrap (all "possible improvement"):
sentry-python:

- [#7400](https://github.com/getsentry/sentry-python/issues/7400) A full `Transaction` is built and
discarded per request when tracing is disabled (~34 µs)
discarded per request when tracing is disabled (~35 µs)
- [#7401](https://github.com/getsentry/sentry-python/issues/7401) `_generate_sample_rand` seeds a
Mersenne Twister per `Transaction`, eagerly, even when unsampled (6.4 µs; 27x cheaper
Mersenne Twister per `Transaction`, eagerly, even when unsampled (6.6 µs; 27x cheaper
arithmetically)
- [#7402](https://github.com/getsentry/sentry-python/issues/7402) `SentryLogsHandler.emit` formats
the record before checking `has_logs_enabled` (~1.9 µs/record)
the record before checking `has_logs_enabled` (~2.4 µs/record)
- Measurements added as a [comment on #2116](https://github.com/getsentry/sentry-python/issues/2116#issuecomment-5565265173),
the long-open "SDK causes significant performance issue" report, rather than filing a duplicate.

Expand Down Expand Up @@ -278,8 +294,9 @@ cd benchmarks
`run.py <suite> --list` prints the scenario names; they are defined in `sentry_scenarios.py`
and `stack_scenarios.py`.
Scenarios whose name implies a fix that does not exist yet (`errors_only_skip_txn`,
`otel_sampler`, `full_all_tuned`) monkeypatch the library to simulate it, so the value of a
proposed change can be measured before anyone writes it.
`errors_only_lazy_sample_rand`) monkeypatch sentry-sdk to simulate it, so the value of a proposed
change can be measured before anyone writes it. The stack suite no longer patches anything: every
scenario there, `full_all_tuned` included, is reachable through `FastAPIConfig`.

`repro_sentry_txn.py` is deliberately standalone - it is the repro pasted into
[sentry-python#7400](https://github.com/getsentry/sentry-python/issues/7400) and imports nothing
Expand Down
63 changes: 12 additions & 51 deletions benchmarks/stack_scenarios.py
Original file line number Diff line number Diff line change
Expand Up @@ -4,8 +4,8 @@
OTLP spans go to `stub_otlp.py` in a separate process so the exporter succeeds instead of
spinning on retry backoff; Sentry events go to `driver.TRANSPORT`.

The `_patch_*` helpers simulate configuration lite-bootstrap does not expose yet
(issues #184 and #185), so the value of exposing it can be measured.
Every scenario here is reachable through `FastAPIConfig`, so a reader can copy the tuned
configuration into their own service and get the measured behaviour.
"""

import os
Expand All @@ -14,14 +14,10 @@
import structlog
from driver import DSN, TRANSPORT
from fastapi import FastAPI
from opentelemetry.instrumentation.fastapi import FastAPIInstrumentor
from opentelemetry.sdk.trace import TracerProvider
from opentelemetry.sdk.trace.sampling import ParentBased, TraceIdRatioBased
from sentry_sdk.integrations.fastapi import FastApiIntegration
from sentry_sdk.integrations.logging import LoggingIntegration
from sentry_sdk.integrations.starlette import StarletteIntegration

import lite_bootstrap.instruments.opentelemetry_instrument as otel_instrument
from lite_bootstrap import FastAPIBootstrapper, FastAPIConfig


Expand All @@ -43,6 +39,8 @@
"opentelemetry_endpoint": OTLP_ENDPOINT,
"opentelemetry_exporter_protocol": "http",
}
_OTEL_EXCLUDE_SPANS: typing.Final = {"opentelemetry_exclude_spans": ["receive", "send"]}
_OTEL_SAMPLER: typing.Final = {"opentelemetry_sampler": ParentBased(TraceIdRatioBased(SAMPLE_RATIO))}
_PROMETHEUS: typing.Final = {"prometheus_metrics_path": "/metrics"}
_LOGGING: typing.Final = {"logging_enabled": True}
_SENTRY: typing.Final = {
Expand All @@ -58,9 +56,10 @@ def _sentry_tuned() -> dict[str, typing.Any]:
"sentry_integrations": [
StarletteIntegration(http_methods_to_capture=()),
FastApiIntegration(http_methods_to_capture=()),
LoggingIntegration(level=None, sentry_logs_level=None),
],
"sentry_additional_params": {"transport": TRANSPORT, "auto_session_tracking": False},
"sentry_logging_breadcrumb_level": None,
"sentry_auto_session_tracking": False,
"sentry_additional_params": {"transport": TRANSPORT},
}


Expand All @@ -86,44 +85,13 @@ def config(*parts: dict[str, typing.Any]) -> dict[str, typing.Any]:
"full_no_otel": lambda: config(_PROMETHEUS, _LOGGING, _SENTRY),
"full_no_sentry": lambda: config(_OTEL, _PROMETHEUS, _LOGGING),
"full_sentry_tuned": lambda: config(_OTEL, _PROMETHEUS, _LOGGING, _sentry_tuned()),
"otel_exclude_spans": lambda: config(_OTEL, _OTEL_EXCLUDE_SPANS),
"otel_sampler": lambda: config(_OTEL, _OTEL_SAMPLER),
"otel_tuned": lambda: config(_OTEL, _OTEL_EXCLUDE_SPANS, _OTEL_SAMPLER),
"full_all_tuned": lambda: config(_OTEL, _OTEL_EXCLUDE_SPANS, _OTEL_SAMPLER, _PROMETHEUS, _LOGGING, _sentry_tuned()),
}


def _patch_exclude_send_receive_spans() -> None:
"""`instrument_app` accepts `exclude_spans`; lite-bootstrap never passes it (issue #185)."""
original = FastAPIInstrumentor.instrument_app

def patched(**kwargs: object) -> None:
kwargs.setdefault("exclude_spans", ["receive", "send"])
original(**typing.cast("dict[str, typing.Any]", kwargs))

FastAPIInstrumentor.instrument_app = staticmethod(patched) # ty: ignore[invalid-assignment]


def _patch_ratio_sampler() -> None:
"""`TracerProvider()` defaults to always-on and no sampler is configurable (issue #184)."""
original = otel_instrument.TracerProvider

def patched(**kwargs: object) -> TracerProvider:
typed = typing.cast("dict[str, typing.Any]", kwargs)
return original(sampler=ParentBased(TraceIdRatioBased(SAMPLE_RATIO)), **typed)

otel_instrument.TracerProvider = patched # ty: ignore[invalid-assignment]


PATCHES: dict[str, list[typing.Callable[[], None]]] = {
"otel_exclude_spans": [_patch_exclude_send_receive_spans],
"otel_sampler": [_patch_ratio_sampler],
"otel_tuned": [_patch_exclude_send_receive_spans, _patch_ratio_sampler],
"full_all_tuned": [_patch_exclude_send_receive_spans, _patch_ratio_sampler],
}

SCENARIOS["otel_exclude_spans"] = SCENARIOS["otel"]
SCENARIOS["otel_sampler"] = SCENARIOS["otel"]
SCENARIOS["otel_tuned"] = SCENARIOS["otel"]
SCENARIOS["full_all_tuned"] = SCENARIOS["full_sentry_tuned"]


def make_app(kind: str) -> FastAPI:
app = FastAPI(docs_url=None, redoc_url=None, openapi_url=None)

Expand All @@ -149,21 +117,14 @@ async def ping_log() -> dict[str, bool]:
return app


def setup(scenario: str) -> None:
"""Apply the patches, then bootstrap. Patches must land before `instrument_app` runs."""
for patch in PATCHES.get(scenario, ()):
patch()


def bootstrap(scenario: str, app: FastAPI) -> None:
FastAPIBootstrapper(FastAPIConfig(application=app, **SCENARIOS[scenario]())).bootstrap()


def build(scenario: str, app_kind: str) -> FastAPI:
setup(scenario)
app = make_app(app_kind)
bootstrap(scenario, app)
return app


__all__ = ["APPS", "PATCHES", "SCENARIOS", "bootstrap", "build", "config", "make_app", "setup"]
__all__ = ["APPS", "SCENARIOS", "bootstrap", "build", "config", "make_app"]
Loading
Loading