Observability that arrives with an import.

00The one-pager

Everything below in a single screen.

01The two-minute answer

Problem → idea → the interesting technical bit → the scale story → outcome.

02Scope & ownership

This one is simpler to describe than most projects, because there is very little to disown: it was my idea, my code, and my rollout.

03How it was built

The commit history is the honest version of the roadmap: a working export path first, then months of making auto-instrumentation correct, then performance, then optionality.

04The problem

Three things were true at once, and only the third one makes this an interesting project.

• Debugging was archaeology. A slow endpoint meant reading logs across services and inferring where the time went. There was no per-function timing inside a request.
• The APM was a line item. Commercial application performance monitoring has a licence cost that scales with hosts and volume, and it was not obviously earning it.
• The obvious fix does not survive contact with a fleet. OpenTelemetry gives HTTP-level spans cheaply. Seeing inside a request means decorating functions by hand — which is a task that competes with feature work in every sprint, in every service, forever. Instrumentation that depends on discipline decays.

05The integration contract

The design goal was a cost of adoption low enough that no team has to schedule it. This is the whole integration.

# server_class.py
from tracer.opentelemetry.tracer import OpenTelemetryTracer

def setup_tracing(self):
    OpenTelemetryTracer(
        fastapi_app=self.app,
        service_name=os.getenv("K_SERVICE", "inventory-smart"),
        tracer_url=os.getenv("APM_TRACE_URL"),
        modules_to_instrument=["inventory_smart"],
    ).instrument()

# pyproject.toml
mtptrace = { git = "…/mtp-trace-backend.git", branch = "main", extras = [] }

modules_to_instrument is the only argument that requires a thought: it is the top-level package of the repository, and it is what keeps the instrumentor from wrapping the entire dependency tree.

Everything else is an environment variable

Every one of those exists because something went wrong once and needed to be changed without a release. A kill switch on a library that touches every function in a service is not a nicety.

06How the wrapping actually works

Three phases, deliberately separated by when they run: once per commit, once per process, and once per call.

Phase 1 — discover the codebase

A tree walk over every .py file, parsed with ast, collecting the name of every function and coroutine defined anywhere in the repository and in any explicitly named package.

class FunctionCollectorHelper(ast.NodeVisitor):
    def visit_FunctionDef(self, node):
        self.defined_functions.add(node.name)
        self.generic_visit(node)

    def visit_AsyncFunctionDef(self, node):
        self.defined_functions.add(node.name)
        self.generic_visit(node)

Phase 2 — cache it against the commit

Both AST passes are proportional to repository size and they ran on every container start. On Cloud Run, where containers start often, that is a cold-start tax on every request that happens to land on a fresh instance. The fix is a cache file whose validity is defined by the commit that produced it.

cache = FunctionsListCacheHandler().load_cache()
latest_hash = FunctionsListCacheHandler().get_git_commit_hash()

if cache.get("hash") == latest_hash:
    return                      # nothing changed, nothing to recompute

# …otherwise rescan and write .functions.list.cache:
{ "hash": "<git rev-parse HEAD>",
  "all_functions": [...],
  "functions_passed_as_argument": [...] }

The commit hash is the right key because it is exactly the thing that determines the answer. A stale cache is not possible: either the code is the code the cache was built from, or the cache is ignored.

Phase 3 — wrap what is already imported

At process start the instrumentor iterates sys.modules, keeps the modules whose names start with one of the configured prefixes, and walks each module's namespace — rebinding eligible functions, and descending into classes to rebind eligible methods.

for module_name in sys.modules:
    if self.should_instrument_module(module_name):
        for name, obj in sys.modules[module_name].__dict__.items():
            if self.is_method(obj):
                setattr(module, name, self.instrument_function(obj))
            elif self.is_class(obj):
                self.instrument_all_methods_in_class(obj)

Wrapping itself is wrapt, with a sync and an async variant selected by inspect.iscoroutinefunction. Each wrapper opens a span, records function.execution_time_ms in a finally block so the timing survives an exception, and re-raises untouched so application error handling is unaffected.

What that one line actually changes

The whole design rests on setattr(module, name, wrapped), and it is worth being precise about it, because it is the question an interviewer will push on. No decorator is ever written into anyone's source. Nothing on disk is rewritten. What happens is a name rebind in a live namespace.

setattr is the dynamic form of dot-assignment — obj.attr = v and setattr(obj, "attr", v) compile to the same thing. It is needed here only because the attribute name is not known when the code is written; it arrives as a loop variable. And a module, once imported, is just an object whose globals live in its __dict__. So for a service file that defines create_order, the instrumentor is performing exactly this:

# sys.modules["inventory_smart.services.order"].__dict__

BEFORE   "create_order" ─────────────────► <function create_order at 0x104a2b0>

AFTER    "create_order" ──► <FunctionWrapper> ──┐
                                                │ .__wrapped__
                                <function create_order at 0x104a2b0>

# equivalent to running, from outside the file:
#   inventory_smart.services.order.create_order = wrapper

The original function object is never touched. It is still the same object at the same address, with the same bytecode; the wrapper merely holds a reference to it, retrievable as __wrapped__. One dictionary value was reassigned. That is the entire mutation.

Why this is enough to trace a whole repository: Python resolves a global or attribute lookup at call time, not at import time. So the swap takes effect for every subsequent call without any cooperation from the calling code — including calls made inside the same file, which resolve through the same __dict__.

That last row is the whole reason the second AST pass exists — it is the same failure described in what made it hard. It also explains why the loop walks every matching module rather than only the file where each function was defined: each import statement created a separate binding, and every one of them has to be caught.

The class case is the same mechanism with a different container. Rebinding in cls.__dict__ means every instance — including ones already constructed — picks up the wrapper on its next call, because instance attribute lookup falls through to the class.

07What made it hard

Wrapping a function is easy. Wrapping every function in a codebase you did not write, without changing its behaviour, is where the months went.

1. Functions used as values

This is the failure that shaped the design. If a function is passed somewhere as an argument — a callback, a key=, a handler registered in a table — then replacing the module attribute with a wrapper changes the object that the receiving code holds. Identity comparisons, signature introspection and equality checks all shift underneath it.

The fix is a second AST pass that looks at every call site, reads the arguments, and collects any argument that names a function the first pass knows about. Those names are excluded from wrapping.

class FunctionArgumentFinderHelper(ast.NodeVisitor):
    def visit_Call(self, node):
        for arg in node.args:
            if isinstance(arg, ast.Name) and arg.id in self.all_functions:
                self.excluded_functions.add(arg.id)
            elif isinstance(arg, ast.Attribute) and isinstance(arg.value, ast.Name):
                if arg.attr in self.all_functions:
                    self.excluded_functions.add(arg.attr)
        self.generic_visit(node)

2. Sync and async are different animals

A single wrapper cannot serve both. An async def returns a coroutine which must be awaited inside the span's context, or the span closes before the work happens and every async function reports near-zero duration. Two wrappers, selected by inspection.

3. Spans with no parent

Function-level instrumentation fires wherever the function is called — including background jobs, startup code and worker threads that are not part of any request. Those produce parentless spans that arrive in the trace list as thousands of fake single-span “traces”. The wrapper checks for a valid current span first, and if there is none, runs the function and emits nothing.

current_span = get_current_span()
if not current_span or not current_span.get_span_context().is_valid:
    return wrapped(*args, **kwargs)     # not part of a request — do not trace

4. Static methods, class methods, threads

Each needed its own detection pass — the history has commits for all three. The lesson is that “a function” in Python is several different objects depending on how it is bound, and code that wraps blindly will get some of them wrong in ways that surface as an AttributeError in someone else's service at deploy time.

5. Third-party packages need different span names

For the service's own code a bare function name is readable. For an instrumented dependency it is ambiguous, so those spans get the fully-qualified module.QualName instead.

08Span volume control

Function-level instrumentation has an obvious failure mode: it multiplies span count per request by the call depth of the application. Left alone, a library like this makes the observability bill the new problem. So the package filters before anything leaves the process.

class DurationFilterSpanProcessor(BatchSpanProcessor):
    def on_end(self, span: ReadableSpan):
        # orphan BigQuery client spans arrive as parentless roots — drop them
        if span.kind == SpanKind.INTERNAL and "bigquery" in span.name.lower() \
                and not span.parent:
            return

        duration_ms = (span.end_time - span.start_time) / 1_000_000
        if duration_ms >= self.duration_threshold_ms \
                or span.status.status_code == StatusCode.ERROR:
            super().on_end(span)
        # else: dropped in-process. no network, no Kafka, no storage.

Two properties of this are worth defending out loud. First, errors bypass the threshold entirely — a 2 ms function that raised is exactly the span you need, and a duration filter that drops it is worse than no filter. Second, the filter runs before the exporter, so a dropped span costs nothing anywhere downstream. Sampling at the collector would already have paid for serialisation and a network hop.

Above the filter sits the standard OTel sampler, configurable per service as always_on, always_off, or partial with a ratio — so a high-traffic service can drop whole traces while a low-traffic one keeps everything.

09Request context & trace–log correlation

A trace is only useful if you can find the one you want. The stock OTel FastAPI instrumentor produces a span per request but knows nothing about the application's notion of a tenant or a user, so the package subclasses it and supplies its own span-detail callback.

def _get_default_span_details(scope):
    route  = _get_route_details(scope)          # matched Starlette route
    method = scope.get("method", "")
    tenant  = scope.get("state", {}).get("tenant")
    user_id = scope.get("state", {}).get("user_id")

    attributes = {}
    if route:   attributes[SpanAttributes.HTTP_ROUTE] = route
    if tenant:  attributes["tenant"] = tenant
    if user_id: attributes["user_id"] = user_id

    return f"{method} {route}", attributes

Using the matched route rather than the raw path is what keeps span names low-cardinality: GET /orders/{id} is one name, not one per order. Tenant and user ride as attributes, which are searchable without becoming part of the name.

Logs point at traces

The other half of the story lives in the shared logging utilities: the current OpenTelemetry trace ID is injected into every log message, and Grafana's derived fields turn it into a link. That is what makes the workflow “this log line looks wrong → open its trace” a click rather than an investigation.

AiopgInstrumentor supplies the last piece — PostgreSQL queries appear as spans in the same waterfall, so a slow function and the slow query inside it sit next to each other.

10Provider independence

The discovery and eligibility machinery — which functions exist, which must not be wrapped, what a span should be called — is entirely independent of where spans go. Late in the project that became explicit: the same instrumentor emits to either backend, chosen per service.

def instrument_function(self, func):
    if self.instrumentation_type == InstrumentationType.DATADOG:
        return ddtrace.tracer.wrap(name=self.get_span_name(func))(func)
    return self._otel_instrument_function(func)

That is a small amount of code for a large amount of freedom. The expensive, hard-won part of this project is the part that decides what to instrument; the part that decides where it goes is a branch. Keeping that boundary clean is what let the organisation move off a commercial APM without rewriting anything in the services.

11Known limits

Bring these up before the interviewer finds them. Knowing where your own design is weak reads as seniority; being surprised by it does not.

12One container → a cluster

What we ran is the small version: services export OTLP straight to a Tempo instance. The interesting design question — and the one worth having an answer to — is what changes when trace volume grows past what one process can hold.

Two independent decisions follow from separating write and read. A query spike must not take ingestion down, and needing more write throughput must not force you to pay for more query capacity. That is the whole argument for the distributed mode in one sentence.

13The trace write path

Why a collector gateway sits in the middle

Every service could point OTLP straight at the Tempo distributor. Putting a collector gateway in between buys three things: services know exactly one URL forever, batching and filtering happen somewhere that can be changed without redeploying applications, and the backend can be swapped without touching a single service's configuration.

Autoscaling the gateway on CPU alone is the mistake worth naming. CPU catches decode and processing saturation, but the queue can grow because Tempo is slow while the collector sits at 40%. The signal that actually means “add replicas” is exporter queue saturation together with accepted spans per replica; dropped spans are an alert, not a scaling input, because by then you are already losing data.

Kafka as the write-ahead log

Inside distributed Tempo, distributors validate and rate-limit OTLP, then write serialised trace records into Kafka. Block-builders consume that stream to build Parquet blocks and flush them to object storage; live-stores consume the same stream to serve recent traces before any block exists.

topic:     tempo-traces
key:       tenant_id + trace_id
partition: hash(trace_id) % partition_count
value:     Tempo's internal serialised span batch

Sharding by trace ID is the load-bearing decision: it keeps one trace's spans on one logical consumer path, which is what makes reassembling the trace tractable later. Partition count is the scale ceiling — too few and adding block-builders does nothing, because there are no more partitions for them to own.

Worth being clear about the boundary: none of that producer/consumer code is something you write. Tempo ships it. The engineering is in partitioning, capacity, retention and monitoring decisions.

14The trace read path

Grafana points at the query frontend, never at individual queriers and never at the write path. The frontend plans and splits a request, queriers execute the subqueries, and results merge before the waterfall renders.

A single trace ID can have spans in a live-store and across several blocks, depending on when the request happened relative to the last flush. The read path merges them into one parent/child graph; the user never learns where any of it was stored.

Reads are far cheaper than writes here — writes happen for every sampled request, reads happen when an engineer is debugging. So the read path starts small, but it needs guardrails: default query windows, maximum lookback, and frontend limits, because one careless seven-day wildcard search can cost more than a thousand normal queries.

15Sizing at 1M spans/sec

spans_per_sec   = requests_per_sec × sampled_ratio × spans_per_sampled_trace

raw_ingest_MBps = spans_per_sec × wire_bytes_per_span / 1e6
stored_TB_day   = spans_per_sec × stored_bytes_per_span × 86,400 / 1e12
retained_TB     = stored_TB_day × retention_days

Span size varies by 5× across those rows, and it moves storage, Kafka throughput, network and block-building pressure by the same factor. That is why any honest starting topology is a range to benchmark rather than a number to deploy.

The load test that makes the numbers real

Four phases — 50K, 250K, 500K, 1M spans/sec — with realistic attribute payloads, because synthetic minimal spans understate every cost in the system. Then two more: kill collectors and block-builders mid-load to watch recovery, and run trace-by-ID and search queries during write load to prove reads do not starve ingestion.

Pass criteria are about saturation, not throughput: queues drain after bursts, dropped spans near zero, Kafka lag bounded and draining, flush latency within target, recent traces queryable within the expected delay.

16The cost model

This is the section that changes how people think about observability, so it is worth leading with the conclusion: at this scale, cost is a volume problem, and the volume dial is sampling policy — not anything in the infrastructure.

The same architecture, the same code, the same retention: $871K a month or $9K a month depending on one configuration decision. Every infrastructure optimisation available in this pipeline lives inside the rounding error of that choice.

17Logs: label cardinality is the whole game

Traces were half the platform. The other half is logs, and the mental model is completely different: Loki is not Elasticsearch. It does not index every word. It indexes labels and stores log lines in compressed chunks — which is what makes it cheap, and what makes it entirely dependent on label design.

A Loki stream is one tenant plus one exact label set. Entries for a stream accumulate into a chunk; chunks flush to object storage when they fill, age out, or go idle.

At 1M events/sec with around 10K healthy streams, each stream sees ~100 events/sec and chunks fill before they age out. Promote trace_id to a label and you have ~1M streams each seeing about one event per second — every chunk flushes on idle timeout while nearly empty, and you have converted a cheap log store into millions of tiny objects, huge ingester memory and slow reads.

18Loki write & read

Batching is what protects the application

At 1M events/sec the application must never call Loki synchronously per line. An agent — Alloy, Fluent Bit, Logstash — batches, parses, enriches, retries and absorbs backpressure. The event rate is fixed; the request rate is a choice.

A starting shape at 1M events/sec and 10K queries/sec

Assuming ~512 B lines, 5:1 compression, 30-day retention and replication factor 3 — about 44 TB/day raw, 8.8 TB/day compressed, ~265 TB retained.

The ingester count looks disproportionate until you remember replication factor 3: the fleet absorbs roughly 3M replicated writes/sec internally, and holds active chunks in memory while it does. Queriers are large for the opposite reason — they are CPU-bound on decompressing and scanning chunks, so read cost is driven by how selective the queries are, not by how many there are.

Rough order for the whole self-managed fleet: $100K–$250K a month, dominated by compute rather than by the ~$6K of object storage. Cost control is the same shape as for traces — drop debug and info logs at source, keep labels low-cardinality, shorten retention, and improve cache hit rate.

19Dashboards & failure modes

Every dashboard here shows traffic and saturation. Traffic alone tells you how much is arriving; saturation tells you whether the next layer is keeping up, which is the thing that actually fails.

20Decision record

21Alternatives, argued fairly

• Just use OpenTelemetry auto-instrumentation. It is excellent, and we use it — for FastAPI and for the database. What it does not do is tell you which of your functions took the time, and that was the actual debugging complaint. mtptrace is a layer above it, not a replacement for it.
• Decorators, done properly. Explicit, precise, no AST tricks, no surprises. Rejected on a social argument rather than a technical one: instrumentation that requires ongoing effort per function converges on the functions somebody was debugging last quarter. If the team were five services instead of dozens, this is probably the right answer.
• A Python profiler or sampling profiler. Better for CPU attribution, worse for the question being asked — which was “where did this request, for this tenant, spend its time”. Traces answer that; profiles do not.
• Keep the commercial APM. Genuinely less work, and better out-of-the-box UI. Rejected on cost once it was clear Tempo plus Grafana covered the debugging workflow we actually used. Trade-off accepted: we own the backend now, including its failure modes.
• Elasticsearch for logs instead of Loki. Full-text indexing is more powerful and much more expensive at this volume. Loki's bet — index labels, compress the rest — is the right one, as long as the label discipline holds. That “as long as” is the whole risk.

22Adoption & influence

A library nobody installs is a side project. Most of the design decisions here are really adoption decisions wearing technical clothes.

• Adoption cost is the product. One constructor call and a dependency line. Every piece of configuration that could be an environment variable is one, so integrating is a PR and not a project.
• Ship the escape hatch with the feature. A kill switch, a per-service threshold, a span-logging exporter. Teams adopt something they can turn off at 2am without a release far more readily than something they cannot.
• Documentation is part of the rollout. A README with the exact code block, the exact environment variables, the known failure (“Cannot install mtptrace” means repository access, not a bug), and a recorded demo of the Grafana workflow.
• DevOps had a separate contract. Their side was environment variables, the Tempo deployment and the Grafana datasource — which is why the responsibility split above is drawn explicitly.
• The logging change was somebody else's repository. Trace–log correlation needed the shared logging utilities to emit the trace ID, so that landed as a PR into a repo I do not own, with its owners.

23Mentorship

This project has a natural mentoring surface that a feature project does not: every integrating team had to be walked through what the library does to their code, and several engineers debugged instrumentation problems with it.

• Teaching the mental model. “Your function is being replaced at import time” is an unfamiliar idea for most application engineers, and it is the thing that makes the failure modes make sense rather than look like magic.
• Turning a bug report into a lesson. The exclusion problem showed up as “my callback broke”. Explaining why teaches how Python treats functions as objects — which is a lesson that outlasts this library.
• Handing over real surface area. The most useful thing to delegate on a platform project is a whole capability with its own failure modes, not a ticket.

24Self-initiated work

This is the project to lead with when someone asks for something proactive rather than assigned. It has the three properties that question is actually testing.

Worth pairing with the reliability and persistence work on the PO allocation platform — that shows self-direction inside an assigned project; this one shows it with no project at all.

25Learning curve

• Metaprogramming is a support commitment. Code that rewrites other people's code produces failures in repositories you have never read, reported by engineers who did not opt in at the function level. Every feature after the first month was really about making those failures rarer or easier to explain.
• Adoption cost dominates capability. A more powerful library that takes a day to integrate loses to a simpler one that takes ten minutes. That is not a compromise; it is the actual optimisation target for platform work.
• The expensive phase and the frequent phase should not be the same phase. Two AST passes are fine once per commit and wrong once per container start. Moving work across that boundary — rather than making it faster — was the whole cold-start fix.
• Telemetry volume is a product decision. Function-level tracing makes span count a function of call depth. Deciding what not to keep turned out to be as much of the design as deciding what to capture.

Ramp-up worth naming honestly: OpenTelemetry's provider/processor/exporter model took real time to internalise, and the first version leaned on print debugging because span pipelines are hard to inspect from the outside — which is why a span-logging exporter is now a first-class feature.

26Outcome & metrics

27The hardest part

Instrumenting code without changing its behaviour

Adding a span is trivial. Guaranteeing that replacing several thousand callables across a repository you did not write leaves every one of them behaving identically is not. Python makes a function an object, and that object gets stored in dictionaries, passed as a callback, compared by identity, inspected for a signature, bound as a method, wrapped in a descriptor, and scheduled on an event loop — and rebinding the name breaks a different one of those each time.

The insight that made it tractable was that the dangerous cases are visible in the source. If a function is passed somewhere as a value, that appears in the AST as an argument to a call — so the codebase can be asked, statically, which functions must be left alone. The design followed from that: a discovery pass, an exclusion pass, and a wrap that only touches what survives both.

It is also the reason the project took ten months rather than three. Each new failure mode — static methods, coroutines, threads, parentless spans — was a real bug in someone's service first and a commit second.

The runner-up: making it not cost what it saved

Two full-repository AST passes on every container start, and a span per function call in a system with deep call stacks. Both were solved by moving work rather than optimising it — the analysis to build time behind a commit-hash cache, and the volume decision into the process, before anything is serialised.

28Question drill

Read the question, answer it out loud, then open the card and compare.

Scope, ownership, leadership

The package

At scale

29What not to say

30Gaps to fill before the interview

Four facts this write-up cannot supply, and each one is a question you will be asked.

• Adoption. Services and teams on it at peak — “org-wide” needs a number behind it.
• Debugging impact. Any measured change in time-to-diagnose, plus one concrete incident it cracked.
• Cost detail. How the ~$21K/yr was calculated, and what it was replacing.
• Mentorship. One engineer: gap, coaching, what they owned afterwards.