Workspace/Lesson workspace
Loading progress
Reliable systems45 min

Tracing the critical path and measuring p95 honestly

Lesson 3 of 3
How to study this lesson

Read one section, trace the worked example, and try the knowledge check. Bookmark saves a shortcut; notes appear in My notebook. Mark lesson complete is your own assessment and does not mark its lab passed.

By the end, you can

  • Represent model and tool work as spans with causal relationships.
  • Compute a defined latency percentile from request-level observations.
  • Separate user latency, worker time, and resource cost.

Metrics tell you where to look

A service dashboard can show that accepted reports became slower, but an average alone does not explain why. A trace records the operations associated with a request and how they relate. OpenTelemetry represents units of work as spans, including identifiers, timestamps, attributes, events, status, and relationships. Instrument logical operations such as route selection, retrieval, model call, tool execution, validation, and response delivery.

Use the same trace context across service boundaries so a queue consumer or tool broker can be connected to the initiating request. A span's parent relationship describes work structure, while links can represent additional causal relationships where appropriate. Avoid pretending that a list of unrelated timestamped log messages is already a distributed trace. The data needs stable correlation and clear semantics about what each measurement represents.

Wall time is not the sum of all spans

Suppose retrieval takes 100 milliseconds, followed by two tools running concurrently for 300 and 500 milliseconds, followed by a 200 millisecond synthesis. The critical path takes 800 milliseconds before overhead: 100 plus max(300, 500) plus 200. Summing tool durations produces 1,100 milliseconds of work, which is useful for resource accounting but incorrect as user latency.

Parent and child spans also overlap by construction. Summing a 900 millisecond request span with all of its child spans double counts time. Measure request latency at the user-facing boundary and use child spans to attribute delay. Queue wait must be included somewhere visible if the user experiences it. A fast worker can coexist with a slow product when requests spend most of their lifetime waiting to start.

Define the percentile estimator and population

A p95 latency is a threshold below which approximately 95 percent of the chosen observations fall. Different estimators interpolate differently, especially for small samples. The example uses the nearest-rank definition: sort n observations and take rank ceiling of 0.95 times n, with ranks starting at one. For 20 observations, that is the nineteenth value.

In a synthetic set containing eighteen 100 millisecond requests, one 900 millisecond request, and one 2,000 millisecond request, the mean is 235 milliseconds and nearest-rank p95 is 900 milliseconds. Both statistics are correct but answer different questions. Report sample count, time window, request population, and treatment of timeouts. Excluding timed-out requests makes latency look better precisely when the user experience may be worsening.

Keep telemetry useful and bounded

Use a few well-defined low-cardinality attributes for aggregate metrics, such as route, operation type, and outcome category. Arbitrary user prompts, document IDs, or full URLs can create excessive metric cardinality and expose sensitive data. Detailed identifiers may belong in access-controlled traces or logs instead. Sampling decisions also matter: a trace sample can help diagnosis, but calculating all-traffic success rates from a biased sample is misleading.

OpenTelemetry's GenAI conventions now have their own official repository. Check the current convention and stability status when selecting field names, and pin the version used by your instrumentation. The example deliberately uses an original local span representation rather than imitating an SDK or claiming protocol compliance. A production integration should use the real SDK, propagate context through queues, export to a configured collector, and test that instrumentation does not break the application.

Connect an incident to a decision

A useful performance investigation asks whether the regression came from routing, longer prompts, provider latency, tool retries, queueing, or verification. Compare request-level metrics with representative traces, then test a focused change. If p95 rises after a cascade rollout, inspect the escalated requests before changing the global timeout. Increasing a timeout may reduce visible failures while increasing the time users wait.

For a portfolio report, include a latency distribution, cost per attempted and accepted task, timeout rate, and a few redacted traces that explain representative paths. Label synthetic experiments as synthetic and avoid presenting their numbers as production results. The strongest conclusion is narrow and actionable: under a documented workload and configuration, a measured change improved a specific metric without violating the stated quality constraints. Observability supplies evidence for that claim; it does not replace an evaluation of answer correctness.

Work through the code

A synthetic request population illustrates nearest-rank p95, and local span dictionaries illustrate overlapping work. They are not OpenTelemetry exports. The wall-time calculation assumes all spans start on one synthetic clock and cover the whole request with no unrepresented queueing.

m23_lesson_3.py
python
from math import ceil
from statistics import mean

def nearest_rank(values, quantile):
    ordered = sorted(values)
    if not ordered or not 0 < quantile <= 1:
        raise ValueError("nonempty values and valid quantile required")
    return ordered[ceil(quantile * len(ordered)) - 1]

latencies = [100] * 18 + [900, 2000]
spans = [
    {"name": "retrieve", "start": 0, "end": 100},
    {"name": "tool-a", "start": 100, "end": 400},
    {"name": "tool-b", "start": 100, "end": 600},
    {"name": "synthesize", "start": 600, "end": 800},
]
work = sum(span["end"] - span["start"] for span in spans)
wall = max(span["end"] for span in spans)
print(f"mean: {mean(latencies):.0f} ms")
print("p95:", nearest_rank(latencies, 0.95), "ms")
print("work:", work, "ms")
print("wall:", wall, "ms")
EXPECTED / ILLUSTRATIVE OUTPUT
mean: 235 ms
p95: 900 ms
work: 1100 ms
wall: 800 ms

Run Python snippets locally with the prerequisites named above. The module coding lab runs directly in your browser.

Pause and reason

A dashboard averages the p95 latency from two workers. Worker A served 1,000 requests and worker B served ten. Why is the result not the service p95, and what should be aggregated instead?

Check your understanding

Two child spans overlap fully, lasting 400 ms and 700 ms. Their parent covers exactly that parallel stage. What is the stage wall time?

Your notes

Explain the mechanism in your own words. Add a failure you want to test.

Saved notes appear in your notebook

Go deeper with primary sources

Practice this module