hamsa software
← All articles
Engineering7 min read

Where did this order spend its time?

A fast request and a fast worker can still leave a customer waiting. Two equal-duration order histories show how queue time, execution and missing evidence lead to different investigations.

A zigzag geometric pulse crosses four concentric elliptical rings, suggesting different intervals within the same order journey.

The slow bit may be between the boxes

The worker took one second. The order took twenty minutes. Both measurements can be right when the order spent most of its time waiting to reach the worker. Making that handler twice as fast would save half a second and leave the customer almost exactly where they started. I would follow the handoff timestamps before deciding which service needs optimising, because the slow part may be the interval neither service currently measures.

An identifier can join the order’s records without explaining the spaces between them. A successful span tells us about the operation it covers; it may omit a queue, a delayed handoff or another local wait. Those intervals need observations of their own. Otherwise the trace is quite capable of assuring us that every measured component was quick while failing to account for most of the time the customer experienced.

OpenTelemetry describes spans as units of work with start and end timestamps, related within traces and through links. [1] That gives a vocabulary for the evidence. The harder design question is which work and waiting periods need to be represented so that the trace answers the person’s actual complaint. “The HTTP request was quick” is not the same answer as “your order moved through the system quickly”.

Two histories, the same twenty minutes

In original history A, an order is accepted at 09:00:00 UTC and enqueued at 09:00:01. A worker starts at 09:20:01 and records downstream completion at 09:20:02. The queue interval is 1200 seconds; worker execution is one second; acceptance to completion is 1202 seconds. Making that one-second worker twice as fast would save half a second from a delay of just over twenty minutes.

History B has the same acceptance and enqueue times, but the worker starts at 09:00:02 and finishes at 09:20:02. Queue wait is one second and execution is 1200 seconds. The end-to-end result is identical. This time, adding queue consumers may not address the cause of that individual slow execution; we need to inspect what the worker spent its time doing. One total latency metric cannot distinguish these two investigations.

The downloadable Python program calculates both histories from declared UTC timestamps. Each totals 1202 seconds, but the long interval belongs to a different stage. That gives a proposed repair a specific outcome to check. In A, restoring timely worker starts should change enqueue-to-start time; in B, it would leave the long execution untouched. Use the synthetic histories to inspect that relationship before applying it to production records, where the meaning and clock basis of each timestamp need checking.

The same total hides opposite bottlenecks

Two original illustrative histories take 20 minutes 2 seconds from acceptance to downstream completion. Their queue and execution times are reversed; optimising the same handler cannot solve both.

Scroll sideways to see all columns.

Event or durationHistory A ·queue waitHistory B ·execution
Accepted09:00:0009:00:00
Enqueued09:00:0109:00:01
Worker started09:20:0109:00:02
Downstream completed09:20:0209:20:02
Queue wait1200 seconds1 second
Worker execution1 second1200 seconds
End-to-end1202 seconds1202 seconds
Synthetic timestamps on a single declared UTC timeline. The downloadable Python file reproduces the durations and illustrates why overlapping spans must not simply be added. These are not measured service timings.

Define the interval before blaming a service

For history A, queue wait means worker-start time minus enqueue time. Be precise about what each timestamp represents. Did enqueue mean the producer began a network request or the broker accepted the message? Did worker start mean delivery to a process, entry to the handler or the start of the business operation after another local wait? Those differences can move time across a chart without making the underlying experience any faster.

Downstream completion needs the same precision. A provider’s acknowledgement can mean it accepted an instruction, rather than that a customer received a message or a supplier fulfilled an order. Measuring that stage is useful if the label says what it means. If the promise concerns a later stage, keep that later observation too, including an unresolved outcome where necessary. A technical success should not gain a more ambitious definition simply because it has moved onto the business dashboard.

The examples use one UTC timeline. Distributed clocks can disagree, so a negative queue interval should prompt an instrumentation check before a capacity purchase. Also distinguish when the order reached a stage from when telemetry arrived: a collector can deliver an old span late. Keep event timestamps and missing observations visible, or a slow reporting path can be mistaken for a slow order and send the investigation towards the wrong service.

Keep the asynchronous relationship visible

An enqueue span often ends before the consumer starts. That does not mean the later processing is unrelated. OpenTelemetry describes links as a way to express causal relationships, including asynchronous work in a later trace. [1] Its messaging conventions also discuss producer, processing and batch relationships. [2] Use the relationships supported by the actual instrumentation rather than forcing every operation into one misleadingly long synchronous parent.

Keep the business operation identifier available alongside the technical trace relationships. A retry may create another attempt, and a batch may process messages belonging to several orders. If the only connection is a timestamp near another timestamp, one busy minute can produce an impressively plausible but wrong reconstruction. The trace should help establish which attempt handled which instruction, while the application record establishes what happened to the order.

A batch can process messages for several orders, while one order can cause several downstream operations. Links preserve those relationships without appointing an arbitrary message as the sole parent. Attribute timing to the order’s actual path; assigning every order the full batch duration as serial waiting would misdescribe its journey.

A waterfall is not a column of numbers to add

Suppose two independent calls each last six seconds and start together. Their durations sum to twelve seconds of operation time, while the elapsed wait for both is six, assuming no other overhead in this small example. That sum does not establish CPU time or other resource consumption. Add parent and child durations together and the same time is counted again. A latency investigation needs intervals and dependencies, not merely a sum of every span exported.

Within history B’s twenty-minute execution, a long parent span could include an external call, backoff, a lock wait or repeated attempts. Meaningful child operations help distinguish those mechanisms. A processor waiting for a dependency may use little CPU during the interval, so extra CPU capacity might have no effect. The trace needs enough detail to test that explanation before resource changes are justified by the parent duration.

For history A, investigate whether consumers were stopped, capacity was insufficient, a subscription was misconfigured or the message waited under a deliberate policy. The queue interval does not prove any one of those causes. Compare another successful order, relevant worker availability and queue evidence for the same period. A trace locates the symptom and constrains hypotheses; causal claims still need evidence connecting the proposed mechanism to the observed delay. Waiting can also be deliberate: a scheduled release may hold an order until its agreed processing time. Distinguish that policy wait from unplanned queue delay before calling every long interval a bottleneck. The business promise determines whether the same elapsed time represents a fault.

Parallel work must not be summed as elapsed waiting

The trace exercise includes two independent six-second calls beginning together.

Follow the labelled arrows. On a narrow screen, scroll sideways if needed.

Parallel work must not be summed as elapsed waitingTwo independent calls begin together. The trace exercise starts call A and call B at the same illustrative time. Call A: 6 seconds. One operation occupies a six-second wall-clock interval. Call B: 6 seconds. A second concurrent operation occupies the same six-second wall-clock interval. Wait for both: 6 seconds. Without other overhead, the shared elapsed interval is six seconds. Summing the call durations gives 12 operation-seconds, not established resource consumption. From Two independent calls begin together to Call A: 6 seconds: Concurrent start. From Two independent calls begin together to Call B: 6 seconds: Concurrent start. From Call A: 6 seconds to Wait for both: 6 seconds: Both must finish. From Call B: 6 seconds to Wait for both: 6 seconds: Both must finish.Concurrent startConcurrent startBoth must finishBoth must finishTwo independent callsbegin togetherThe trace exercise startscall A and call B at the sameillustrative time.Call A: 6 secondsOne operation occupies asix-second wall-clockinterval.Call B: 6 secondsA second concurrent operationoccupies the same six-secondwall-clock interval.Wait for both: 6secondsWithout other overhead, theshared elapsed interval issix seconds. Summing the calldurations gives 12operation-seconds, notestablished resourceconsumption.
Adding parent and child spans can double-count the same elapsed time; dependencies determine the relevant journey.

Let the finding change a decision

The first improvement might be instrumentation: a durable enqueue-accepted timestamp, a worker-start event or a downstream reference. Add the observation that would distinguish the remaining explanations, rather than collecting every payload field because storage is available. Order identifiers and stage metadata may be enough; private message contents can create exposure without making the timing question easier to answer.

Check the change against the interval it was meant to improve. Restoring paused consumers in history A should reduce the wait; adjusting their queue would not establish that history B’s slow dependency improved. Then look at the whole journey again. A component can become quicker while moving time into another unmeasured handoff, which would make its team’s chart more satisfying without giving the customer an earlier result.

One order can give a clear account of this particular wait and point to an observation still missing. Deciding how much to invest needs a wider view of how often that cause appears and what it costs the service. Keep the individual history alongside those population measurements. The customer is entitled to an answer about this order; the team needs another answer about whether the same explanation justifies a broader change.

Working on a workflow like this? Hamsa helps finance and operations teams connect their tools and handle the exceptions, starting with one workflow.

See the Payment Operations Pilot

References & further reading

Primary sources behind this article. Living documentation may change.

  1. OpenTelemetry: traces, spans, timestamps and causal links
  2. OpenTelemetry: messaging span relationships and batch links
Hamsa Jama

Practical engineering. A human perspective.

More about Hamsa Software and the person behind it. Editorial notes.

A few more things
worth a read.

Back to the reading room
Engineering7 min read

What does £240 belong to?

A readable table preserves relationships between values, row labels, column headings and actions across different ways of reading.

Engineering7 min read

When two calculations agree on the wrong answer

A shadow comparison exposes differences. Independent rule examples explain whether those differences are bugs, corrections or changed assumptions.