diff --git a/benchmarks/README.md b/benchmarks/README.md index 133d4e5..f38751e 100644 --- a/benchmarks/README.md +++ b/benchmarks/README.md @@ -3,7 +3,7 @@ ## 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. @@ -11,7 +11,7 @@ Two published figures about the Sentry half look contradictory and are both corr 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 @@ -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. @@ -47,41 +47,47 @@ structlog 26.1.0. Endpoint: `async def` returning `{"ok": True}`. Median of 5 ro ## 3. Headline numbers + 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. + -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: + | 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 | | + + +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. @@ -89,10 +95,10 @@ until you actually log. | 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 @@ -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: + | 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 | | + 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 @@ -128,23 +136,25 @@ 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 @@ -152,13 +162,15 @@ 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. @@ -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`): + | 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 | + `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 @@ -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 - @@ -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: + ```python FastAPIConfig( # Sentry: OTel owns distributed tracing, Sentry is an error sink @@ -209,6 +224,7 @@ FastAPIConfig( opentelemetry_sampler=ParentBased(TraceIdRatioBased(0.01)), ) ``` + 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. @@ -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. @@ -278,8 +294,9 @@ cd benchmarks `run.py --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 diff --git a/benchmarks/stack_scenarios.py b/benchmarks/stack_scenarios.py index ea89a90..e41ff6f 100644 --- a/benchmarks/stack_scenarios.py +++ b/benchmarks/stack_scenarios.py @@ -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 @@ -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 @@ -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 = { @@ -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}, } @@ -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) @@ -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"] diff --git a/docs/introduction/configuration.md b/docs/introduction/configuration.md index 52256d5..1ea9e2d 100644 --- a/docs/introduction/configuration.md +++ b/docs/introduction/configuration.md @@ -15,7 +15,7 @@ Additional parameters can also be supplied through the settings object: - `sentry_max_breadcrumbs` - the total amount of breadcrumbs - `sentry_max_value_length` - the max event payload length - `sentry_attach_stacktrace` - if True, stack traces are automatically attached to all messages logged -- `sentry_auto_session_tracking` - whether every request opens and closes a Sentry release-health `Session` (default: `True`), measured at ~7 µs per request. Set it to `False` if you do not use Sentry release health. +- `sentry_auto_session_tracking` - whether every request opens and closes a Sentry release-health `Session` (default: `True`), measured at ~7.7 µs per request. Set it to `False` if you do not use Sentry release health. - `sentry_integrations` - list of integrations to enable - `sentry_logging_breadcrumb_level` - the minimum standard-library log level recorded as a breadcrumb (default: `logging.INFO`). Passed as `LoggingIntegration(level=...)`; see below. - `sentry_tags` - key/value string pairs that are both indexed and searchable @@ -25,6 +25,9 @@ Additional parameters can also be supplied through the settings object: Read more about sentry_sdk params [here](https://docs.sentry.io/platforms/python/configuration/options/). +Sentry is the second most expensive instrument in the stack, and the settings that actually move +the number are not the ones most people reach for. See [Performance](performance.md). + ### Sentry logging integration Unless `sentry_integrations` already contains a `LoggingIntegration`, lite-bootstrap appends one built @@ -37,8 +40,7 @@ off, but `SentryLogsHandler.emit` formats the record *before* it checks whether ([getsentry/sentry-python#7402](https://github.com/getsentry/sentry-python/issues/7402)) - it formats every `INFO`+ record and discards the result. Dropping breadcrumbs as well, with `sentry_logging_breadcrumb_level=None`, saves more but costs you log breadcrumbs on error events, so -it stays on by default. Both are measured in -[the benchmarks](https://github.com/modern-python/lite-bootstrap/blob/main/benchmarks/README.md#4c-logging-cost-per-record-not-per-request). +it stays on by default. Both are measured on the [performance page](performance.md#where-the-time-goes). Two ways to opt out of the appended integration: supply your own `LoggingIntegration` in `sentry_integrations`, which lite-bootstrap leaves untouched, or set @@ -48,6 +50,8 @@ Under either, `sentry_logging_breadcrumb_level` is ignored and lite-bootstrap wa ## Prometheus +Prometheus is the cheapest of the three non-logging instruments; see [Performance](performance.md). + To bootstrap Prometheus, you must provide at least: - `prometheus_metrics_path`. @@ -106,6 +110,7 @@ Additional parameters: Sampling is the cheapest way to cut what tracing costs: on a benchmark endpoint returning a constant, `ParentBased(TraceIdRatioBased(0.01))` saved ~55 µs per request against the always-on default. +OpenTelemetry is the most expensive instrument in the stack; see [Performance](performance.md). ```python from opentelemetry.sdk.trace.sampling import ParentBased, TraceIdRatioBased @@ -120,7 +125,7 @@ config = FastAPIConfig( For FastAPI there is additionally: - `opentelemetry_exclude_spans` - drops the ASGI `receive` and/or `send` spans, leaving only the - server span. Empty by default, which records all three. `["receive", "send"]` is worth ~33 µs per + server span. Empty by default, which records all three. `["receive", "send"]` is worth ~34 µs per request on the benchmark endpoint, at the cost of two thirds of the spans disappearing from your trace view. @@ -153,6 +158,9 @@ When OpenTelemetry is also enabled, a `PyroscopeSpanProcessor` is automatically Structlog is bootstrapped by default. To opt out, set `logging_enabled=False`. +Configuring it costs almost nothing; the cost arrives per log record, and most of it is Sentry's. +See [Performance](performance.md). + Additional parameters: - `logging_enabled` - whether to configure structlog (default: `True`). diff --git a/docs/introduction/performance.md b/docs/introduction/performance.md new file mode 100644 index 0000000..56330a7 --- /dev/null +++ b/docs/introduction/performance.md @@ -0,0 +1,86 @@ +# Performance + +Turning on the observability stack is not free, and the ordering of what costs what is not the one +most people expect. This page is the short version of +[the benchmark write-up](https://github.com/modern-python/lite-bootstrap/blob/main/benchmarks/README.md), +which has the method, the full ablations and the commands to reproduce everything here. + +## The short answer + +Measured on a trivial `async def` endpoint returning `{"ok": True}`, uvicorn with a single worker, +loaded with `ab -k -c 16 -n 20000`: + +--8<-- "benchmarks/README.md:headline" + +Tuning is worth **+80% RPS** on the real server, and every setting behind it is a documented +[configuration](configuration.md) field. + +## Where the time goes + +Each instrument alone, driving the ASGI app in-process so only library cost shows: + +--8<-- "benchmarks/README.md:perinstrument" + +Four things here are worth knowing before you tune anything: + +- **OpenTelemetry costs about twice what Sentry does**, and is the dominant cost of the stack. Most + people assume Sentry is the expensive one. +- **Structlog costs nothing until you actually log.** `LoggingInstrument` adds ~0.1 µs per request + when configured. The cost arrives per record, not per request, and most of it is Sentry's two + log handlers: on a three-record endpoint Sentry costs 12.3 µs per record, of which those + handlers are 9.6. +- **`sentry_traces_sample_rate=1.0` costs a further +353 µs per request.** If you set it, set it + next to a sample rate you actually want. +- **The Sentry knobs people reach for do nothing.** This is the useful negative result: + +--8<-- "benchmarks/README.md:sentryablation" + +`attach_stacktrace`, `max_breadcrumbs` and dropping the default integrations all measure inside +noise. Essentially the entire cost is the ASGI integration, and over half of that is a `Transaction` +built and discarded because `sentry_traces_sample_rate` is unset. + +## If you are RPS-constrained, start here + +In rough order of what they return: + +| setting | saves | what you give up | +|---|---|---| +| [`opentelemetry_sampler`](configuration.md#opentelemetry), 1% ratio | ~55 µs/req | 99% of your traces | +| `http_methods_to_capture=()` on the Sentry ASGI integrations | ~35 µs/req | Sentry-side trace correlation | +| [`opentelemetry_exclude_spans`](configuration.md#opentelemetry), FastAPI only | ~34 µs/req | the two ASGI event spans | +| [`sentry_auto_session_tracking=False`](configuration.md#sentry) | ~7.7 µs/req | Sentry release health | +| [`sentry_logging_breadcrumb_level=None`](configuration.md#sentry-logging-integration) | ~7 µs per log record | log breadcrumbs on errors | + +Together those are worth ~132 µs per request against the ~136 µs the tuned row actually recovers, +so there is nothing else material hiding in it. That configuration is: + +--8<-- "benchmarks/README.md:tuned" + +lite-bootstrap already applies one saving for you: it passes `sentry_logs_level=None` by default, +because it never enables Sentry Logs and the handler formats every record before checking whether +they are enabled. That one costs nothing, which is why it is a default rather than a knob. + +## What each saving costs you + +Speed alone does not settle whether a setting is worth changing. Measured by capturing a real error +event with an incoming `sentry-trace` header and inspecting the envelope: + +--8<-- "benchmarks/README.md:tradeoffs" + +The row that needs a decision is `http_methods_to_capture=()`: the error event gets a fresh +`trace_id` and no `parent_span_id`, so errors stop correlating across services in Sentry. Take it +when OpenTelemetry owns distributed tracing and Sentry is only an error sink, which is the case in +any service running `OpenTelemetryInstrument`. Do not take it otherwise. + +## The caveat that matters most + +These ratios are an upper bound. The endpoint measured here does nothing, so the fixed per-request +cost of the stack is compared against an unrealistically small denominator. A service that does real +work per request, a database round trip or a downstream call, pays the same absolute cost against a +much larger one. + +**Read the µs columns, not the percentages.** A stack that costs 70% of a do-nothing handler's +throughput costs a few percent of a handler that waits 5 ms on a database. + +Numbers are machine-specific and move a few percent between runs. The ordering and the ratios are +the durable part. diff --git a/mkdocs.yml b/mkdocs.yml index 4ccbb5f..0044bac 100644 --- a/mkdocs.yml +++ b/mkdocs.yml @@ -9,6 +9,7 @@ nav: - Quickstart: introduction/quickstart.md - Installation: introduction/installation.md - Configuration: introduction/configuration.md + - Performance: introduction/performance.md - Integrations: - Litestar: integrations/litestar.md - FastStream: integrations/faststream.md @@ -74,7 +75,11 @@ markdown_extensions: - pymdownx.tabbed: alternate_style: true - pymdownx.inlinehilite - - pymdownx.snippets + # Reaches benchmarks/README.md, outside docs_dir: the performance page shares its tables + # rather than keeping a second copy of the numbers, and check_paths makes a move fail loudly. + - pymdownx.snippets: + base_path: ["."] + check_paths: true - pymdownx.superfences - def_list - codehilite: