diff --git a/benchmarks/README.md b/benchmarks/README.md new file mode 100644 index 0000000..db4ca67 --- /dev/null +++ b/benchmarks/README.md @@ -0,0 +1,288 @@ +# What the observability stack costs a lite-bootstrap FastAPI service + +## 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 +**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 +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 +does real work per request - a database round trip, a downstream call - pays the same absolute +cost against a much larger denominator, so read the µs columns rather than the percentages. + +## 2. Method + +Two suites - `sentry` (one `sentry_sdk.init()` knob at a time) and `stack` (the lite-bootstrap +instruments, configured through `FastAPIBootstrapper`) - measured three ways: + +- **In-process** (`run.py`) - drives the ASGI app directly (`await app(scope, receive, send)`), no + sockets, no HTTP parsing. Isolates library cost; overstates the *relative* impact because the + 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). +- **Micro** (`micro.py`, `verify.py`, `profile_one.py`) - per-operation costs, what each + configuration actually gives up, and cProfile. + +Each scenario runs in its own process. `sentry_sdk.init()` monkeypatches `Starlette.__call__`, +`Middleware.__init__` and `logging.Logger.callHandlers`; `set_tracer_provider` is set-once per +process; the Prometheus registry is global. None of it can be undone in-process. + +Sentry events go to a null transport that still serializes the envelope, so transport CPU is +counted but network is not. OTLP spans go to a stub HTTP sink in a separate process that returns +200, so the exporter succeeds instead of spinning on retry backoff. + +Environment: Apple M2 (8 cores), macOS 26.6.2, CPython 3.14.7, sentry-sdk 2.67.1, fastapi 0.141.1, +starlette 1.6.0, uvicorn 0.52.1, opentelemetry-sdk 1.44.0, +opentelemetry-instrumentation-fastapi 0.65b0, prometheus-fastapi-instrumentator 8.1.0, +structlog 26.1.0. Endpoint: `async def` returning `{"ok": True}`. Median of 5 rounds. + +## 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% | + +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% | + +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 +order of magnitude of a do-nothing handler's throughput. + +## 4. Per-instrument breakdown + +In-process, each instrument alone, baseline 15.8 µ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 +twice Sentry**, which was not the expected ordering, and structlog's instrument costs nothing +until you actually log. + +### 4a. OpenTelemetry: two knobs lite-bootstrap does not expose + +| 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** | + +1. `FastAPIInstrumentor.instrument_app` accepts `exclude_spans: list[Literal["receive","send"]]`. + lite-bootstrap passes only `app`, `tracer_provider` and `excluded_urls`, so **every request + produces three spans** - the server span plus one each for the ASGI `receive` and `send` + events. Two thirds of the spans, one quarter of the cost, and almost nobody looks at them. +2. `OpenTelemetryInstrument.bootstrap()` constructs `TracerProvider(resource=resource)` with no + sampler, which means the SDK default `parentbased_always_on`. **There is no configuration + surface for a sampler anywhere in lite-bootstrap**, so a service cannot head-sample its own + traces at all; every request is recorded, serialized and shipped. A 1% ratio sampler is worth + 55 µs/req here. (Sampling rate is a user decision, not a default to change - the gap is that + it cannot be expressed.) + +### 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: + +| 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 | | + +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 +thrown away because tracing is disabled. + +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 | +| `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 +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 +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%). + +### 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 | + +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. +`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. + +This hits lite-bootstrap directly because `LoggingInstrument` wires structlog through +`structlog.stdlib.BoundLogger`, so every structlog call goes through the patched +`logging.Logger.callHandlers` and pays both handlers. + +## 5. What each saving actually costs you + +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** | +| 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 +distributed tracing is OpenTelemetry's job - as it is in any lite-bootstrap service that also runs +`OpenTelemetryInstrument` - and Sentry is only an error sink. Not acceptable otherwise. + +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. + +Similarly, `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. + +## 6. The tuned configuration + +What "tuned" means in §3, all reachable through today's public API except the two OTel knobs: + +```python +FastAPIConfig( + # Sentry: OTel owns distributed tracing, Sentry is an error sink + sentry_integrations=[ + StarletteIntegration(http_methods_to_capture=()), + FastApiIntegration(http_methods_to_capture=()), + LoggingIntegration(level=None, sentry_logs_level=None), + ], + sentry_additional_params={"auto_session_tracking": False}, + # OpenTelemetry: not expressible today, see issues + # exclude_spans=["receive", "send"] on FastAPIInstrumentor.instrument_app + # sampler=ParentBased(TraceIdRatioBased(0.01)) on TracerProvider +) +``` + +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. + +## 7. Filed issues + +lite-bootstrap (all "possible improvement", nothing implemented): + +- [#184](https://github.com/modern-python/lite-bootstrap/issues/184) OpenTelemetry sampler is not + configurable (55 µs/req) +- [#185](https://github.com/modern-python/lite-bootstrap/issues/185) `exclude_spans` is never passed + to `FastAPIInstrumentor` (33 µs/req) +- [#186](https://github.com/modern-python/lite-bootstrap/issues/186) Sentry `sentry_logs_level`, + breadcrumb level and `auto_session_tracking` are not exposed (~9 µs/req plus ~2 µs/log record) +- [#187](https://github.com/modern-python/lite-bootstrap/issues/187) Document what the stack costs + +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) +- [#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 + arithmetically) +- [#7402](https://github.com/getsentry/sentry-python/issues/7402) `SentryLogsHandler.emit` formats + the record before checking `has_logs_enabled` (~1.9 µ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. + +Related existing reports: [#2303](https://github.com/getsentry/sentry-python/issues/2303), +[#668](https://github.com/getsentry/sentry-python/issues/668). + +## 8. Reproducing + +Everything runs from this directory against an interpreter that has `lite_bootstrap`, `fastapi`, +`uvicorn`, `structlog`, `sentry-sdk`, the OpenTelemetry SDK and +`prometheus-fastapi-instrumentator` importable - the repo's own `.venv` does. Each runner +re-invokes `sys.executable` once per scenario, because none of the patching these libraries do at +import or init time can be undone in-process. + +```bash +cd benchmarks + +# per-instrument breakdown and the tuned stack (section 4) +../.venv/bin/python run.py stack async bare,log,prom,sentry,otel,full,full_all_tuned + +# the two OpenTelemetry knobs (section 4a) +../.venv/bin/python run.py stack async otel,otel_exclude_spans,otel_sampler,otel_tuned + +# the Sentry ablation, where every familiar knob turns out to be a no-op (section 4b) +../.venv/bin/python run.py sentry async off,errors_only,errors_only_lean,errors_only_no_integrations,errors_only_no_txn + +# cost per log record (section 4c) +../.venv/bin/python run.py sentry logging off,errors_only,errors_only_no_sentry_logs,errors_only_logging_lean + +# the headline numbers, over real sockets - needs `ab` on PATH +../.venv/bin/python run_http.py stack async bare,full,full_all_tuned + +# what a scenario gives up, and where the time goes inside one +../.venv/bin/python verify.py errors_only_no_txn +../.venv/bin/python micro.py +../.venv/bin/python profile_one.py sentry errors_only +../.venv/bin/python profile_one.py sentry errors_only --callers 'Random.seed' +``` + +`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. + +`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 +from this directory. + +Numbers are machine-specific and move a few percent run to run; the ratios and the ordering are +the durable part. Everything here was measured in one session on one idle machine, which is the +only way the columns are comparable to each other. diff --git a/benchmarks/driver.py b/benchmarks/driver.py new file mode 100644 index 0000000..6be9eca --- /dev/null +++ b/benchmarks/driver.py @@ -0,0 +1,108 @@ +"""Shared pieces: a null Sentry transport and an in-process ASGI request loop. + +Driving the app directly (`await app(scope, receive, send)`) removes sockets and HTTP parsing +from the measurement, so what is left is library cost. It makes the baseline unrealistically +fast, which overstates the *relative* impact; `run_http.py` is the real-server counterpart. +""" + +import asyncio +import gc +import time +import typing + + +if typing.TYPE_CHECKING: + from sentry_sdk.envelope import Envelope + +from sentry_sdk.transport import Transport + + +DSN: typing.Final = "https://public@o0.ingest.sentry.io/0" + +ASGIApp = typing.Callable[..., typing.Awaitable[None]] + + +class NullTransport(Transport): + """Serialize the envelope and drop it: transport CPU is counted, network is not.""" + + def __init__(self, options: dict[str, typing.Any] | None = None) -> None: + super().__init__(options) + self.envelopes = 0 + self.bytes = 0 + + def capture_envelope(self, envelope: "Envelope") -> None: + self.envelopes += 1 + self.bytes += len(envelope.serialize()) + + +TRANSPORT: typing.Final = NullTransport() + + +BASE_SCOPE: typing.Final[dict[str, typing.Any]] = { + "type": "http", + "asgi": {"version": "3.0", "spec_version": "2.3"}, + "http_version": "1.1", + "method": "GET", + "scheme": "http", + "path": "/ping", + "raw_path": b"/ping", + "root_path": "", + "query_string": b"", + "headers": [ + (b"host", b"testserver"), + (b"user-agent", b"bench/1.0"), + (b"accept", b"*/*"), + (b"connection", b"keep-alive"), + ], + "client": ("127.0.0.1", 50000), + "server": ("127.0.0.1", 8000), +} + + +async def one_request(app: ASGIApp, scope: dict[str, typing.Any] | None = None) -> int: + """Drive one request through the ASGI app and return its status code. + + The scope is copied per call because Starlette and the instrumentations write into it + (`route`, `endpoint`, `app`, ...), exactly as a real server hands over a fresh one. + """ + request_scope = dict(scope if scope is not None else BASE_SCOPE) + status = 0 + body_sent = False + + async def receive() -> dict[str, typing.Any]: + nonlocal body_sent + if body_sent: + return {"type": "http.disconnect"} + body_sent = True + return {"type": "http.request", "body": b"", "more_body": False} + + async def send(message: dict[str, typing.Any]) -> None: + nonlocal status + if message["type"] == "http.response.start": + status = message["status"] + + await app(request_scope, receive, send) + return status + + +async def run(app: ASGIApp, requests: int, rounds: int, warmup: int) -> list[float]: + """Return one requests-per-second figure per round.""" + expected_status = 200 + for _ in range(warmup): + status = await one_request(app) + if status != expected_status: + msg = f"warmup returned {status}, expected {expected_status}" + raise RuntimeError(msg) + + results = [] + for _ in range(rounds): + gc.collect() + start = time.perf_counter() + for _ in range(requests): + await one_request(app) + results.append(requests / (time.perf_counter() - start)) + return results + + +def measure(app: ASGIApp, requests: int, rounds: int, warmup: int) -> list[float]: + return asyncio.run(run(app, requests, rounds, warmup)) diff --git a/benchmarks/inprocess.py b/benchmarks/inprocess.py new file mode 100644 index 0000000..8010200 --- /dev/null +++ b/benchmarks/inprocess.py @@ -0,0 +1,54 @@ +"""Run one scenario in this process and write its requests-per-second rounds to a file. + +One process per scenario is not tidiness: `sentry_sdk.init()` monkeypatches Starlette and the +stdlib logging module, `set_tracer_provider` is set-once, and the Prometheus registry is +global. Nothing here can be undone between scenarios. +""" + +import argparse +import contextlib +import importlib +import io +import json +import logging +import pathlib +import types + +import driver + + +class _Sink(io.TextIOBase): + """Swallow the app's own stdout (structlog writes there) without buffering it.""" + + def write(self, s: str) -> int: + return len(s) + + +def load_suite(name: str) -> types.ModuleType: + return importlib.import_module(f"{name}_scenarios") + + +def main() -> None: + parser = argparse.ArgumentParser(description=__doc__) + parser.add_argument("--suite", required=True, choices=["sentry", "stack"]) + parser.add_argument("--scenario", required=True) + parser.add_argument("--app", default="async") + parser.add_argument("--requests", type=int, default=5000) + parser.add_argument("--rounds", type=int, default=5) + parser.add_argument("--warmup", type=int, default=500) + parser.add_argument("--out", required=True, type=pathlib.Path) + args = parser.parse_args() + + logging.basicConfig(level=logging.INFO, stream=_Sink()) + logging.getLogger("opentelemetry").setLevel(logging.CRITICAL) + + suite = load_suite(args.suite) + with contextlib.redirect_stdout(_Sink()): + app = suite.build(args.scenario, args.app) + rps = driver.measure(app, args.requests, args.rounds, args.warmup) + + args.out.write_text(json.dumps({"suite": args.suite, "scenario": args.scenario, "app": args.app, "rps": rps})) + + +if __name__ == "__main__": + main() diff --git a/benchmarks/micro.py b/benchmarks/micro.py new file mode 100644 index 0000000..ae7a852 --- /dev/null +++ b/benchmarks/micro.py @@ -0,0 +1,69 @@ +"""Per-operation costs of the pieces sentry-sdk runs on every request. + +Attributes the per-request total from `run.py` to individual calls, which is what makes the +upstream issues actionable: `Transaction(...)` and the Mersenne Twister seed inside it are the +two largest items, and neither is reachable from a configuration knob. +""" + +import statistics +import timeit +import typing +import uuid +from random import Random + +import sentry_scenarios +import sentry_sdk +from sentry_sdk.scope import Scope +from sentry_sdk.tracing import Transaction +from sentry_sdk.tracing_utils import Baggage, PropagationContext, _generate_sample_rand + + +HEADERS: typing.Final = { + "host": "testserver", + "user-agent": "bench/1.0", + "accept": "*/*", + "connection": "keep-alive", +} +TRACE_ID: typing.Final = uuid.uuid4().hex + + +def timed(label: str, stmt: typing.Callable[[], object], number: int = 20000, repeat: int = 5) -> None: + times = timeit.repeat(stmt, number=number, repeat=repeat) + best = min(times) / number * 1e6 + median = statistics.median(times) / number * 1e6 + print(f"{label:<46} {best:>8.2f} us (best) {median:>8.2f} us (med)") + + +def main() -> None: + sentry_sdk.init(**sentry_scenarios.base_kwargs(max_breadcrumbs=15, attach_stacktrace=True)) + scope = Scope.get_isolation_scope() + + def start_and_finish() -> None: + transaction = Transaction(op="http.server", name="GET /ping", source="route") + with sentry_sdk.start_transaction(transaction, custom_sampling_context={"asgi_scope": {}}): + pass + + def isolation() -> None: + with sentry_sdk.isolation_scope(): + pass + + timed("uuid4().hex", lambda: uuid.uuid4().hex) + timed("Random(trace_id)", lambda: Random(TRACE_ID)) # noqa: S311 + timed("_generate_sample_rand(trace_id)", lambda: _generate_sample_rand(TRACE_ID)) + timed("PropagationContext()", PropagationContext) + timed("PropagationContext.from_incoming_data(headers)", lambda: PropagationContext.from_incoming_data(HEADERS)) + timed("Baggage.from_incoming_header(None)", lambda: Baggage.from_incoming_header(None)) + timed("scope.generate_propagation_context(headers)", lambda: scope.generate_propagation_context(HEADERS)) + timed( + "scope.continue_trace(headers)", + lambda: scope.continue_trace(HEADERS, op="http.server", name="GET /ping", source="route"), + ) + timed("Transaction(op, name, source)", lambda: Transaction(op="http.server", name="GET /ping", source="route")) + timed("start_transaction(txn) + exit (tracing off)", start_and_finish, number=5000) + timed("isolation_scope() enter/exit", isolation) + timed("scope.fork()", scope.fork) + timed("get_client()", sentry_sdk.get_client) + + +if __name__ == "__main__": + main() diff --git a/benchmarks/profile_one.py b/benchmarks/profile_one.py new file mode 100644 index 0000000..dafcac0 --- /dev/null +++ b/benchmarks/profile_one.py @@ -0,0 +1,60 @@ +"""cProfile one scenario's request loop. + +The absolute numbers are inflated (the profiler roughly triples per-request cost); the call +counts and the relative ordering are what this is for. `ncalls` divided by the request count is +often the finding on its own. + + python profile_one.py sentry errors_only + python profile_one.py stack otel --sort cumtime +""" + +import argparse +import asyncio +import contextlib +import cProfile +import io +import logging +import pstats + +import driver +from inprocess import load_suite + + +def main() -> None: + parser = argparse.ArgumentParser(description=__doc__) + parser.add_argument("suite", choices=["sentry", "stack"]) + parser.add_argument("scenario") + parser.add_argument("--app", default="async") + parser.add_argument("--requests", type=int, default=3000) + parser.add_argument("--sort", default="tottime") + parser.add_argument("--rows", type=int, default=30) + parser.add_argument("--callers", help="regex; print what calls the matching functions instead") + args = parser.parse_args() + + logging.basicConfig(level=logging.INFO, stream=io.StringIO()) + logging.getLogger("opentelemetry").setLevel(logging.CRITICAL) + + sink = io.StringIO() + with contextlib.redirect_stdout(sink): + app = load_suite(args.suite).build(args.scenario, args.app) + driver.measure(app, 500, 1, 200) + + async def body() -> None: + for _ in range(args.requests): + await driver.one_request(app) + + profiler = cProfile.Profile() + profiler.enable() + asyncio.run(body()) + profiler.disable() + + stats = pstats.Stats(profiler).sort_stats(args.sort) + print(f"{args.suite}/{args.scenario} app={args.app} requests={args.requests}\n") + if args.callers: + stats.print_callers(args.callers) + else: + stats.print_stats(args.rows) + + +if __name__ == "__main__": + main() diff --git a/benchmarks/repro_sentry_txn.py b/benchmarks/repro_sentry_txn.py new file mode 100644 index 0000000..ac4cd17 --- /dev/null +++ b/benchmarks/repro_sentry_txn.py @@ -0,0 +1,99 @@ +"""Standalone repro for getsentry/sentry-python#7400, kept copy-pasteable. + +Deliberately imports nothing from this directory: it is pasted into the upstream issue and has +to run against a bare `pip install sentry-sdk fastapi` checkout. Importing sentry-sdk patches +nothing - only `init()` does - so `--off` is a genuine no-SDK baseline. + + python repro_sentry_txn.py --off # SDK never initialised + python repro_sentry_txn.py # SDK as shipped + python repro_sentry_txn.py --patched # skip the Transaction, keep trace propagation +""" + +import asyncio +import sys +import time +import typing + +import sentry_sdk +from fastapi import FastAPI +from sentry_sdk.envelope import Envelope +from sentry_sdk.scope import Scope +from sentry_sdk.transport import Transport + + +SCOPE: typing.Final = { + "type": "http", + "asgi": {"version": "3.0", "spec_version": "2.3"}, + "http_version": "1.1", + "method": "GET", + "scheme": "http", + "path": "/ping", + "raw_path": b"/ping", + "root_path": "", + "query_string": b"", + "headers": [(b"host", b"testserver"), (b"accept", b"*/*")], + "client": ("127.0.0.1", 50000), + "server": ("127.0.0.1", 8000), +} +WARMUP: typing.Final = 500 +REQUESTS: typing.Final = 5000 + + +class NullTransport(Transport): + def capture_envelope(self, envelope: Envelope) -> None: + """Drop it: this measures instrumentation, not delivery.""" + + +def continue_trace_without_transaction( + self: Scope, environ_or_headers: dict[str, typing.Any], *_args: object, **_kwargs: object +) -> None: + """Set up trace propagation only, as the SDK could when tracing is disabled.""" + self.generate_propagation_context(environ_or_headers) + + +def setup(*, patched: bool) -> None: + # tracing is DISABLED: traces_sample_rate and traces_sampler are both unset + sentry_sdk.init(dsn="https://public@o0.ingest.sentry.io/0", transport=NullTransport) + if patched: + Scope.continue_trace = continue_trace_without_transaction # ty: ignore[invalid-assignment] + + +async def drive(app: typing.Callable[..., typing.Awaitable[None]], requests: int) -> float: + async def receive() -> dict[str, typing.Any]: + return {"type": "http.request", "body": b"", "more_body": False} + + async def send(message: dict[str, typing.Any]) -> None: + """Discard the response.""" + + for _ in range(WARMUP): + await app(dict(SCOPE), receive, send) + + start = time.perf_counter() + for _ in range(requests): + await app(dict(SCOPE), receive, send) + return requests / (time.perf_counter() - start) + + +def main() -> None: + if "--patched" in sys.argv: + mode = "patched" + elif "--off" in sys.argv: + mode = "off" + else: + mode = "sdk" + + if mode != "off": + setup(patched=mode == "patched") + + app = FastAPI(docs_url=None, redoc_url=None, openapi_url=None) + + @app.get("/ping") + async def ping() -> dict[str, bool]: + return {"ok": True} + + rps = asyncio.run(drive(app, REQUESTS)) + print(f"{mode:<8} {rps:8.0f} rps {1e6 / rps:6.1f} us/req") + + +if __name__ == "__main__": + main() diff --git a/benchmarks/run.py b/benchmarks/run.py new file mode 100644 index 0000000..b162f64 --- /dev/null +++ b/benchmarks/run.py @@ -0,0 +1,103 @@ +"""Run a set of in-process scenarios, one subprocess each, and print the comparison table. + + python run.py sentry async off,errors_only,errors_only_no_txn + python run.py stack async bare,otel,prom,sentry,full,full_all_tuned + +The first scenario in the list is the baseline the rest are compared against. +""" + +import argparse +import json +import pathlib +import statistics +import subprocess +import sys +import tempfile +import time + +from inprocess import load_suite + + +HERE = pathlib.Path(__file__).resolve().parent +STUB_OTLP_PORT = "8139" + + +def bench(suite: str, scenario: str, app: str, requests: int, rounds: int) -> list[float]: + with tempfile.TemporaryDirectory() as tmp: + out = pathlib.Path(tmp) / "result.json" + subprocess.run( # noqa: S603 + [ + sys.executable, + str(HERE / "inprocess.py"), + "--suite", + suite, + "--scenario", + scenario, + "--app", + app, + "--requests", + str(requests), + "--rounds", + str(rounds), + "--out", + str(out), + ], + check=True, + cwd=HERE, + stdout=subprocess.DEVNULL, + ) + return json.loads(out.read_text())["rps"] + + +def report(suite: str, app: str, requests: int, rounds: int, scenarios: list[str]) -> None: + print(f"{suite} suite app={app} requests={requests} rounds={rounds}\n") + print(f"{'scenario':<38} {'rps(med)':>10} {'us/req':>9} {'vs base':>8} {'+us':>8}") + baseline = None + for scenario in scenarios: + median = statistics.median(bench(suite, scenario, app, requests, rounds)) + micros = 1e6 / median + if baseline is None: + baseline = micros + print(f"{scenario:<38} {median:>10.0f} {micros:>9.1f} {baseline / micros:>7.2f}x {micros - baseline:>+8.1f}") + + +def main() -> None: + parser = argparse.ArgumentParser(description=__doc__) + parser.add_argument("suite", choices=["sentry", "stack"]) + parser.add_argument("app", nargs="?", default="async") + parser.add_argument("scenarios", nargs="?", help="comma-separated; the first one is the baseline") + parser.add_argument("--list", action="store_true", help="print this suite's scenario names and exit") + parser.add_argument("--requests", type=int, default=4000) + parser.add_argument("--rounds", type=int, default=5) + args = parser.parse_args() + + suite = load_suite(args.suite) + if args.list: + print("\n".join(sorted(suite.SCENARIOS))) + return + if not args.scenarios: + parser.error("give a comma-separated scenario list, or --list to see the names") + + scenarios = args.scenarios.split(",") + unknown = sorted(set(scenarios) - set(suite.SCENARIOS)) + if unknown: + parser.error(f"unknown {args.suite} scenarios: {', '.join(unknown)}") + + stub = None + if args.suite == "stack": + stub = subprocess.Popen( # noqa: S603 + [sys.executable, str(HERE / "stub_otlp.py"), STUB_OTLP_PORT], + stdout=subprocess.DEVNULL, + stderr=subprocess.DEVNULL, + ) + time.sleep(1.0) + try: + report(args.suite, args.app, args.requests, args.rounds, scenarios) + finally: + if stub is not None: + stub.terminate() + stub.wait(timeout=10) + + +if __name__ == "__main__": + main() diff --git a/benchmarks/run_http.py b/benchmarks/run_http.py new file mode 100644 index 0000000..ac88330 --- /dev/null +++ b/benchmarks/run_http.py @@ -0,0 +1,142 @@ +"""Same comparison as `run.py`, but over real sockets: uvicorn plus `ab -k`. + + python run_http.py sentry async off,errors_only,traces_1 + python run_http.py stack async bare,full,full_all_tuned + +Needs `ab` (Apache Bench) on PATH. Check the load generator is not the ceiling before +trusting a run: raise `--concurrency` on the baseline scenario until the number stops moving. +""" + +import argparse +import pathlib +import re +import statistics +import subprocess +import sys +import time +import typing +import urllib.error +import urllib.request + +from inprocess import load_suite + + +HERE = pathlib.Path(__file__).resolve().parent +PORT = 8137 +STUB_OTLP_PORT = "8139" +RPS_RE = re.compile(r"Requests per second:\s+([0-9.]+)") +WARMUP_REQUESTS = 2000 +HTTP_OK = 200 + + +class Load(typing.NamedTuple): + requests: int + concurrency: int + rounds: int + + +def _probe(port: int) -> bool: + try: + with urllib.request.urlopen(f"http://127.0.0.1:{port}/ping", timeout=1) as response: + return response.status == HTTP_OK + except (urllib.error.URLError, OSError): + return False + + +def wait_ready(port: int, timeout: float = 20.0) -> None: + deadline = time.time() + timeout + while time.time() < deadline: + if _probe(port): + return + time.sleep(0.1) + msg = f"server on port {port} did not become ready" + raise RuntimeError(msg) + + +def ab(port: int, requests: int, concurrency: int) -> float: + result = subprocess.run( # noqa: S603 + ["ab", "-k", "-q", "-n", str(requests), "-c", str(concurrency), f"http://127.0.0.1:{port}/ping"], # noqa: S607 + capture_output=True, + text=True, + check=True, + ) + match = RPS_RE.search(result.stdout) + if match is None: + msg = f"could not parse ab output:\n{result.stdout}{result.stderr}" + raise RuntimeError(msg) + return float(match.group(1)) + + +def bench(suite: str, scenario: str, app: str, load: Load) -> list[float]: + server = subprocess.Popen( # noqa: S603 + [ + sys.executable, + str(HERE / "serve.py"), + "--suite", + suite, + "--scenario", + scenario, + "--app", + app, + "--port", + str(PORT), + ], + cwd=HERE, + stdout=subprocess.DEVNULL, + stderr=subprocess.DEVNULL, + ) + try: + wait_ready(PORT) + ab(PORT, WARMUP_REQUESTS, load.concurrency) + return [ab(PORT, load.requests, load.concurrency) for _ in range(load.rounds)] + finally: + server.terminate() + server.wait(timeout=10) + time.sleep(0.5) + + +def report(suite: str, app: str, load: Load, scenarios: list[str]) -> None: + print(f"uvicorn + ab -k {suite} suite app={app} n={load.requests} c={load.concurrency} rounds={load.rounds}\n") + print(f"{'scenario':<38} {'rps(med)':>10} {'us/req':>9} {'vs base':>8} {'+us':>8}") + baseline = None + for scenario in scenarios: + median = statistics.median(bench(suite, scenario, app, load)) + micros = 1e6 / median + if baseline is None: + baseline = micros + print(f"{scenario:<38} {median:>10.0f} {micros:>9.1f} {baseline / micros:>7.2f}x {micros - baseline:>+8.1f}") + + +def main() -> None: + parser = argparse.ArgumentParser(description=__doc__) + parser.add_argument("suite", choices=["sentry", "stack"]) + parser.add_argument("app") + parser.add_argument("scenarios", help="comma-separated; the first one is the baseline") + parser.add_argument("--requests", type=int, default=20000) + parser.add_argument("--concurrency", type=int, default=16) + parser.add_argument("--rounds", type=int, default=3) + args = parser.parse_args() + + scenarios = args.scenarios.split(",") + unknown = sorted(set(scenarios) - set(load_suite(args.suite).SCENARIOS)) + if unknown: + parser.error(f"unknown {args.suite} scenarios: {', '.join(unknown)}") + + stub = None + if args.suite == "stack": + stub = subprocess.Popen( # noqa: S603 + [sys.executable, str(HERE / "stub_otlp.py"), STUB_OTLP_PORT], + stdout=subprocess.DEVNULL, + stderr=subprocess.DEVNULL, + ) + time.sleep(1.0) + try: + report(args.suite, args.app, Load(args.requests, args.concurrency, args.rounds), scenarios) + finally: + if stub is not None: + stub.terminate() + stub.wait(timeout=10) + + +if __name__ == "__main__": + main() diff --git a/benchmarks/sentry_scenarios.py b/benchmarks/sentry_scenarios.py new file mode 100644 index 0000000..331158f --- /dev/null +++ b/benchmarks/sentry_scenarios.py @@ -0,0 +1,220 @@ +"""`sentry_sdk.init()` configurations, isolating what each knob costs per request. + +Every scenario runs in its own process: `init()` monkeypatches `Starlette.__call__`, +`starlette.middleware.Middleware.__init__` and `logging.Logger.callHandlers`, and none of it +can be undone. + +The `*_patch` scenarios are not configurations a user can reach - they simulate an upstream +fix so its value can be measured before proposing it. +""" + +import logging +import typing + +import sentry_sdk +import sentry_sdk.tracing +from driver import DSN, TRANSPORT +from fastapi import FastAPI +from sentry_sdk.integrations.dedupe import DedupeIntegration +from sentry_sdk.integrations.excepthook import ExcepthookIntegration +from sentry_sdk.integrations.fastapi import FastApiIntegration +from sentry_sdk.integrations.logging import LoggingIntegration +from sentry_sdk.integrations.modules import ModulesIntegration +from sentry_sdk.integrations.starlette import StarletteIntegration +from sentry_sdk.integrations.stdlib import StdlibIntegration +from sentry_sdk.integrations.threading import ThreadingIntegration +from sentry_sdk.scope import Scope + + +logger = logging.getLogger("bench") + +APPS: typing.Final = ("async", "sync", "logging") + + +def base_kwargs(**overrides: object) -> dict[str, typing.Any]: + return { + "dsn": DSN, + "transport": TRANSPORT, + "environment": "bench", + "release": "bench@1", + **overrides, + } + + +# The default integrations that patch global machinery; the framework ones are not here. +def _lean_integrations() -> list[typing.Any]: + return [ + StdlibIntegration(), + ModulesIntegration(), + DedupeIntegration(), + ExcepthookIntegration(), + ThreadingIntegration(), + ] + + +def _no_transaction_integrations() -> list[typing.Any]: + return [ + StarletteIntegration(http_methods_to_capture=()), + FastApiIntegration(http_methods_to_capture=()), + ] + + +SCENARIOS: dict[str, typing.Callable[[], dict[str, typing.Any]] | None] = { + "off": None, + # lite-bootstrap's own defaults: tracing off, all default and auto integrations on. + "errors_only": lambda: base_kwargs( + max_breadcrumbs=15, + max_value_length=16384, + attach_stacktrace=True, + ), + # --- knobs people reach for first --- + "errors_only_no_stacktrace": lambda: base_kwargs(max_breadcrumbs=15, attach_stacktrace=False), + "errors_only_no_breadcrumbs": lambda: base_kwargs(max_breadcrumbs=0, attach_stacktrace=True), + "errors_only_lean": lambda: base_kwargs( + max_breadcrumbs=15, + attach_stacktrace=True, + disabled_integrations=_lean_integrations(), + ), + "errors_only_no_logging_integration": lambda: base_kwargs( + max_breadcrumbs=15, + attach_stacktrace=True, + disabled_integrations=[LoggingIntegration()], + ), + "errors_only_no_default_integrations": lambda: base_kwargs( + default_integrations=False, + integrations=[StarletteIntegration(), FastApiIntegration()], + ), + # init() called, nothing patched: the floor for "the SDK is loaded". + "errors_only_no_integrations": lambda: base_kwargs( + default_integrations=False, + auto_enabling_integrations=False, + integrations=[], + ), + # --- ablations of the framework integration's per-request work --- + "errors_only_no_sessions": lambda: base_kwargs( + max_breadcrumbs=15, + attach_stacktrace=True, + auto_session_tracking=False, + ), + "errors_only_no_txn": lambda: base_kwargs( + max_breadcrumbs=15, + attach_stacktrace=True, + integrations=_no_transaction_integrations(), + ), + "errors_only_no_sessions_no_txn": lambda: base_kwargs( + max_breadcrumbs=15, + attach_stacktrace=True, + auto_session_tracking=False, + integrations=_no_transaction_integrations(), + ), + "errors_only_starlette_only": lambda: base_kwargs( + max_breadcrumbs=15, + attach_stacktrace=True, + auto_enabling_integrations=False, + integrations=[StarletteIntegration()], + ), + "errors_only_txn_endpoint_style": lambda: base_kwargs( + max_breadcrumbs=15, + attach_stacktrace=True, + integrations=[ + StarletteIntegration(transaction_style="endpoint"), + FastApiIntegration(transaction_style="endpoint"), + ], + ), + # --- logging integration knobs --- + "errors_only_no_sentry_logs": lambda: base_kwargs( + max_breadcrumbs=15, + attach_stacktrace=True, + integrations=[LoggingIntegration(sentry_logs_level=None)], + ), + "errors_only_logging_lean": lambda: base_kwargs( + max_breadcrumbs=15, + attach_stacktrace=True, + integrations=[LoggingIntegration(level=None, sentry_logs_level=None)], + ), + # --- tracing on --- + "traces_0": lambda: base_kwargs(traces_sample_rate=0.0, attach_stacktrace=True), + "traces_01": lambda: base_kwargs(traces_sample_rate=0.1, attach_stacktrace=True), + "traces_1": lambda: base_kwargs(traces_sample_rate=1.0, attach_stacktrace=True), + "traces_1_lean": lambda: base_kwargs( + traces_sample_rate=1.0, + attach_stacktrace=True, + disabled_integrations=_lean_integrations(), + ), +} + + +def _patch_lazy_sample_rand() -> None: + """`Transaction.__init__` derives sample_rand from the trace id even when tracing is off.""" + sentry_sdk.tracing._generate_sample_rand = lambda trace_id, **kwargs: 0.5 # ty: ignore[invalid-assignment] # noqa: ARG005 + + +def _patch_skip_transaction() -> None: + """Keep trace propagation, but don't build a Transaction that can never be sampled.""" + + def continue_trace( + self: Scope, environ_or_headers: dict[str, typing.Any], *_args: object, **_kwargs: object + ) -> None: + self.generate_propagation_context(environ_or_headers) + + Scope.continue_trace = continue_trace # ty: ignore[invalid-assignment] + + +PATCHES: dict[str, list[typing.Callable[[], None]]] = { + "errors_only_lazy_sample_rand": [_patch_lazy_sample_rand], + "errors_only_skip_txn": [_patch_skip_transaction], + "errors_only_skip_txn_no_sessions": [_patch_skip_transaction], + "errors_only_logging_lean_skip_txn": [_patch_skip_transaction], +} + +SCENARIOS["errors_only_lazy_sample_rand"] = SCENARIOS["errors_only"] +SCENARIOS["errors_only_skip_txn"] = SCENARIOS["errors_only"] +SCENARIOS["errors_only_skip_txn_no_sessions"] = SCENARIOS["errors_only_no_sessions"] +SCENARIOS["errors_only_logging_lean_skip_txn"] = SCENARIOS["errors_only_logging_lean"] + + +def setup(scenario: str) -> None: + factory = SCENARIOS[scenario] + if factory is not None: + sentry_sdk.init(**factory()) + for patch in PATCHES.get(scenario, ()): + patch() + + +def make_app(kind: str) -> FastAPI: + app = FastAPI(docs_url=None, redoc_url=None, openapi_url=None) + + if kind == "async": + + @app.get("/ping") + async def ping() -> dict[str, bool]: + return {"ok": True} + + elif kind == "sync": + + @app.get("/ping") + def ping_sync() -> dict[str, bool]: + return {"ok": True} + + elif kind == "logging": + + @app.get("/ping") + async def ping_log() -> dict[str, bool]: + logger.info("handling request", extra={"a": 1}) + logger.info("did a thing", extra={"b": 2}) + logger.info("done", extra={"c": 3}) + return {"ok": True} + + else: + msg = f"unknown app kind: {kind}" + raise ValueError(msg) + + return app + + +def build(scenario: str, app_kind: str) -> FastAPI: + setup(scenario) + return make_app(app_kind) + + +__all__ = ["APPS", "PATCHES", "SCENARIOS", "base_kwargs", "build", "make_app", "setup"] diff --git a/benchmarks/serve.py b/benchmarks/serve.py new file mode 100644 index 0000000..5bade25 --- /dev/null +++ b/benchmarks/serve.py @@ -0,0 +1,28 @@ +"""Serve one scenario under uvicorn so it can be loaded over real sockets. + +Paired with `run_http.py`, which starts this and points `ab` at it. +""" + +import argparse +import logging + +import uvicorn +from inprocess import load_suite + + +def main() -> None: + parser = argparse.ArgumentParser(description=__doc__) + parser.add_argument("--suite", required=True, choices=["sentry", "stack"]) + parser.add_argument("--scenario", required=True) + parser.add_argument("--app", default="async") + parser.add_argument("--port", type=int, default=8137) + args = parser.parse_args() + + app = load_suite(args.suite).build(args.scenario, args.app) + logging.getLogger().setLevel(logging.CRITICAL) + + uvicorn.run(app, host="127.0.0.1", port=args.port, access_log=False, log_level="error") + + +if __name__ == "__main__": + main() diff --git a/benchmarks/stack_scenarios.py b/benchmarks/stack_scenarios.py new file mode 100644 index 0000000..ea89a90 --- /dev/null +++ b/benchmarks/stack_scenarios.py @@ -0,0 +1,169 @@ +"""The whole lite-bootstrap observability stack, one instrument at a time and combined. + +Configured through `FastAPIBootstrapper`, so these are the costs a real service pays. +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. +""" + +import os +import typing + +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 + + +OTLP_PORT: typing.Final = int(os.environ.get("STUB_OTLP_PORT", "8139")) +OTLP_ENDPOINT: typing.Final = f"http://127.0.0.1:{OTLP_PORT}/v1/traces" +SAMPLE_RATIO: typing.Final = 0.01 + +APPS: typing.Final = ("async", "structlog") + +log = structlog.get_logger("bench") + +_EVERYTHING_OFF: typing.Final = { + "prometheus_metrics_path": "", + "health_checks_enabled": False, + "swagger_offline_docs": False, + "logging_enabled": False, +} +_OTEL: typing.Final = { + "opentelemetry_endpoint": OTLP_ENDPOINT, + "opentelemetry_exporter_protocol": "http", +} +_PROMETHEUS: typing.Final = {"prometheus_metrics_path": "/metrics"} +_LOGGING: typing.Final = {"logging_enabled": True} +_SENTRY: typing.Final = { + "sentry_dsn": DSN, + "sentry_additional_params": {"transport": TRANSPORT}, +} + + +def _sentry_tuned() -> dict[str, typing.Any]: + """Sentry as an error sink only: OpenTelemetry owns distributed tracing here.""" + return { + "sentry_dsn": DSN, + "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}, + } + + +def config(*parts: dict[str, typing.Any]) -> dict[str, typing.Any]: + merged = { + "service_name": "bench", + "service_environment": "bench", + "service_debug": False, + **_EVERYTHING_OFF, + } + for part in parts: + merged.update(part) + return merged + + +SCENARIOS: dict[str, typing.Callable[[], dict[str, typing.Any]]] = { + "bare": config, + "otel": lambda: config(_OTEL), + "prom": lambda: config(_PROMETHEUS), + "log": lambda: config(_LOGGING), + "sentry": lambda: config(_SENTRY), + "full": lambda: config(_OTEL, _PROMETHEUS, _LOGGING, _SENTRY), + "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()), +} + + +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) + + if kind == "async": + + @app.get("/ping") + async def ping() -> dict[str, bool]: + return {"ok": True} + + elif kind == "structlog": + + @app.get("/ping") + async def ping_log() -> dict[str, bool]: + log.info("handling request", a=1) + log.info("did a thing", b=2) + log.info("done", c=3) + return {"ok": True} + + else: + msg = f"unknown app kind: {kind}" + raise ValueError(msg) + + 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"] diff --git a/benchmarks/stub_otlp.py b/benchmarks/stub_otlp.py new file mode 100644 index 0000000..50597fb --- /dev/null +++ b/benchmarks/stub_otlp.py @@ -0,0 +1,27 @@ +"""Minimal OTLP/HTTP sink so the exporter succeeds instead of retrying with backoff. + +A dead endpoint would leave the exporter thread spinning on retries, which shows up as noise in +the request-path measurement. Started and stopped by `run.py` / `run_http.py` for the stack suite. +""" + +import sys +from http.server import BaseHTTPRequestHandler, ThreadingHTTPServer + + +class Handler(BaseHTTPRequestHandler): + def do_POST(self) -> None: + length = int(self.headers.get("content-length", 0)) + if length: + self.rfile.read(length) + self.send_response(200) + self.send_header("content-type", "application/x-protobuf") + self.send_header("content-length", "0") + self.end_headers() + + def log_message(self, format: str, *args: object) -> None: # noqa: A002 + """Silence the default stderr access log.""" + + +if __name__ == "__main__": + port = int(sys.argv[1]) + ThreadingHTTPServer(("127.0.0.1", port), Handler).serve_forever() diff --git a/benchmarks/verify.py b/benchmarks/verify.py new file mode 100644 index 0000000..663f5d9 --- /dev/null +++ b/benchmarks/verify.py @@ -0,0 +1,110 @@ +"""What a cheaper Sentry configuration actually gives up. + +Speed alone does not settle whether a scenario is worth adopting. This drives a request that +raises, with an incoming `sentry-trace` header, and prints what survived on the captured event: +the transaction name, whether the incoming distributed trace was continued, and the breadcrumbs. + + python verify.py errors_only errors_only_no_txn errors_only_skip_txn +""" + +import argparse +import asyncio +import contextlib +import io +import json +import logging +import sys +import typing + +import driver +import sentry_scenarios +import sentry_sdk +from fastapi import FastAPI +from sentry_sdk.envelope import Envelope +from sentry_sdk.transport import Transport + + +INCOMING_TRACE_ID: typing.Final = "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa" +INCOMING_SPAN_ID: typing.Final = "bbbbbbbbbbbbbbbb" + +logger = logging.getLogger("bench") + + +class CapturingTransport(Transport): + def __init__(self, options: dict[str, typing.Any] | None = None) -> None: + super().__init__(options) + self.events: list[dict[str, typing.Any]] = [] + + def capture_envelope(self, envelope: Envelope) -> None: + for item in envelope.items: + if item.type == "event" and item.payload.json is not None: + self.events.append(item.payload.json) + + +def make_app() -> FastAPI: + app = FastAPI(docs_url=None, redoc_url=None, openapi_url=None) + + @app.get("/ping") + async def ping() -> dict[str, bool]: + logger.info("about to fail") + msg = "boom" + raise RuntimeError(msg) + + return app + + +def traced_scope() -> dict[str, typing.Any]: + scope = dict(driver.BASE_SCOPE) + scope["headers"] = [ + *driver.BASE_SCOPE["headers"], + (b"sentry-trace", f"{INCOMING_TRACE_ID}-{INCOMING_SPAN_ID}-1".encode()), + (b"baggage", f"sentry-trace_id={INCOMING_TRACE_ID},sentry-environment=prod".encode()), + ] + return scope + + +async def drive(app: driver.ASGIApp) -> None: + with contextlib.suppress(RuntimeError): + await driver.one_request(app, traced_scope()) + + +def describe(scenario: str, event: dict[str, typing.Any]) -> dict[str, typing.Any]: + trace = (event.get("contexts") or {}).get("trace") or {} + breadcrumbs = (event.get("breadcrumbs") or {}).get("values") or [] + return { + "scenario": scenario, + "transaction": event.get("transaction"), + "trace_id": trace.get("trace_id"), + "parent_span_id": trace.get("parent_span_id"), + "continues_incoming_trace": trace.get("trace_id") == INCOMING_TRACE_ID, + "breadcrumbs": [crumb.get("message") for crumb in breadcrumbs], + "request_url": (event.get("request") or {}).get("url"), + } + + +def main() -> None: + parser = argparse.ArgumentParser(description=__doc__) + parser.add_argument("scenario") + args = parser.parse_args() + + logging.basicConfig(level=logging.INFO, stream=io.StringIO()) + + transport = CapturingTransport() + kwargs = sentry_scenarios.SCENARIOS[args.scenario] + if kwargs is None: + parser.error("scenario 'off' captures nothing") + init_kwargs = kwargs() + init_kwargs["transport"] = transport + sentry_sdk.init(**init_kwargs) + for patch in sentry_scenarios.PATCHES.get(args.scenario, ()): + patch() + + asyncio.run(drive(make_app())) + + for event in transport.events: + json.dump(describe(args.scenario, event), sys.stdout) + sys.stdout.write("\n") + + +if __name__ == "__main__": + main() diff --git a/pyproject.toml b/pyproject.toml index 7dc7514..eef20a3 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -188,6 +188,7 @@ isort.no-lines-before = ["standard-library", "local-folder"] [tool.ruff.lint.per-file-ignores] "scripts/*.py" = ["INP001"] # standalone scripts, not an importable package +"benchmarks/*.py" = ["INP001", "T201", "SLF001"] # standalone scripts: print tables, read SDK internals [tool.pytest.ini_options] addopts = "--cov=. --cov-report term-missing --cov-fail-under=100"