Why Did Botie Take So Long?

A technician asks Botie which inspection procedure applies to pump 7. He finds the manual and gives a useful answer, but it takes much longer than yesterday. Was the manual search slow? Did a tool fail and retry? Did Botie keep asking the model for something he already had?

The final answer has thrown away most of that story. We need a record of the operations that produced it, with their relationships and timings still attached. Then we can change the part that actually caused the delay.

Select one request, find its root span, and measure its elapsed time. Compare that result with the child intervals when two tools overlap.

800

A span is a record for one operation. Give it a useful name, a start time and an end time. A manual lookup might also record which document version it searched and whether the service returned an error.

A log line tells us that something happened at a moment. A span gives the operation a duration. Both can be useful, provided we can connect them to the same request.

Begin with boundaries you can act on: the request, a retrieval call, a model call and any tool whose failures matter.

A trace groups the spans belonging to one request. Each span has its own ID, and a child records the ID of the operation that started it. The request span has no parent in our complete fixture.

Two technicians can call the same tool at the same time. A tool name and timestamp alone cannot reliably tell us which request produced which call. The trace and parent IDs preserve that relationship.

A parent describes causal context. It does not imply that siblings ran one after another.

Botie can request the manual and equipment details concurrently. On our table, both operations are active for part of the same interval. Adding their durations counts that shared time twice.

For the technician’s elapsed wait, measure the root request. To investigate its slow path, examine when dependencies actually finished and what the next operation was waiting for. Adding every descendant also double counts nested spans.

Request duration = end − start
Request duration = 900 − 0 = 900 milliseconds

A sum of span durations is not automatically CPU time, either. An operation can spend much of its duration waiting on a network.

Suppose manual search times out and succeeds on the second attempt. Recording only the successful call hides the first delay and its failure. Keep an enclosing operation and separate attempts, or otherwise record attempt numbers and errors clearly.

Marking an HTTP call successful only says it returned normally under that call’s definition. A model response can still cite the wrong manual. Later lessons will attach quality judgements separately.

The trace should let us distinguish a slow successful call from a quick failure followed by a second call.

When Botie calls another service, that service needs the current trace context if its work is to appear in the same trace. Instrumentation can inject that context into a request and extract it at the receiver. OpenTelemetry commonly uses the W3C traceparent header for this.

If propagation is lost, the receiver may create a new root. The work still happened, but the picture becomes disconnected. For queued or fan-in work, span links can express relationships that do not fit one parent.

Do not infer that missing spans mean no work occurred. First check instrumentation, propagation and sampling.

A dictionary keeps a timestamp beside its meaning. A list contains several span records. Selecting a trace should happen before choosing the root; otherwise another technician’s request can supply the duration by accident.

This small program inspects recorded data. It does not install a tracer or send telemetry.

spans = [
    {"id": "request", "parent": None, "start": 10, "end": 210},
    {"id": "manual", "parent": "request", "start": 20, "end": 170},
]
roots = [s for s in spans if s["parent"] is None]
print(roots[0]["id"])
print(roots[0]["end"] - roots[0]["start"])

request
200

A tracer creates spans. An SDK provider collects them, and an exporter sends them somewhere we can inspect. Start with the console exporter so we can see a small record without configuring a hosted dashboard.

The nested context manager below establishes the parent relationship for a local lookup. A real remote client also needs propagation. Use instrumentation suited to that client instead of assuming a Python with block follows an HTTP request into another process.

This example records a real local function execution. Its tiny in-memory manual is still a fixture, and it performs no model inference.

from opentelemetry import trace
from opentelemetry.sdk.trace import TracerProvider
from opentelemetry.sdk.trace.export import SimpleSpanProcessor, ConsoleSpanExporter

provider = TracerProvider()
provider.add_span_processor(SimpleSpanProcessor(ConsoleSpanExporter()))
trace.set_tracer_provider(provider)
tracer = trace.get_tracer("perceptronlab.maintenance")

with tracer.start_as_current_span("maintenance-request"):
    with tracer.start_as_current_span("manual-lookup") as lookup:
        manual = {"P7": "Request inspection before restart."}.get("P7")
        lookup.set_attribute("manual.found", manual is not None)

provider.shutdown()

Record usage on the model generation that consumed it. Input tokens and output tokens can have different prices, and caching or other provider categories may change the bill. Keep the model identifier and the pricing assumptions with a cost estimate.

A parent summary may already include its children’s usage. Summing that summary with those same children charges the work twice. A retry that reached the provider may add usage even if the application later discarded its answer.

Illustrative input cost = (1200 / 1000000) × 2 = 0.0024 currency units
Illustrative output cost = (300 / 1000000) × 8 = 0.0024 currency units
Estimated generation cost = 0.0024 + 0.0024 = 0.0048 currency units

These rates are invented to show the calculation. Use the actual provider’s pricing categories and usage records for accounting.

A technician’s request can contain names, internal equipment locations or secrets pasted by mistake. Logging every prompt verbatim creates another copy of that information. Decide which fields are necessary before exporting them.

For our maintenance flow, a document version and a controlled error code may answer the debugging question without retaining the full manual. Redact before export, restrict access, and set retention deliberately. Do not put credentials or personal information in tracing baggage that may travel to other services.

Record boundary decisions where the application makes them: the policy revision, the resource identity and an access-controlled reason code for an allowed or denied action. Link the decision to its action ID so a later investigator can distinguish a blocked attempt from a write that actually happened. Do not copy secrets or hidden model reasoning to explain that decision.

A redacted trace should still preserve operation identities and relationships. Redaction that removes every useful distinction makes diagnosis harder.

One trace explains one recorded execution. Metrics can tell us whether slow requests are becoming common, while logs can retain details of a particular error. Correlating them lets us move from a rising error rate to an example of the failing path.

Sampling reduces the stored trace volume. A sampled set can miss rare failures, and selecting only slow traces biases latency summaries. Record the sampling policy and compute service-wide metrics from appropriate observations.

A missing failure in the viewer is weak evidence if the relevant request was never retained.

If retrieval dominates the elapsed time, changing the answer prompt may barely change the wait. If repeated model calls dominate, inspect the loop’s stopping rule and what each call receives. If the root has a large unexplained gap, instrument that gap before guessing.

Compare the repaired request with fresh requests under similar conditions. Keep quality checks beside timing so an answer that arrives quickly but ignores the manual does not look like a successful repair.

Botie’s workshop measures the root of a chosen trace. The changed case introduces overlap, and the fresh case mixes in another request to test whether the construction still follows the right technician.