FIX Order Latency: Measure Ack, Fill and Cancel Times from a FIX Log

What the analyzer shows

New order to ack

From a New Order Single (35=D) or New Order Multileg (35=AB) to the first Execution Report (35=8) for the same order. That report is normally 150=0 (New) or 150=A (Pending New); when the first answer is a reject or an immediate fill, that report is the ack.

New order to first fill

From the new order to the first Execution Report with ExecType 1, 2 or F. It includes the time the order rests before it trades, so it measures the market as well as the systems.

Cancel to confirmation

From each Order Cancel Request (35=F) to its answer: an Execution Report with ExecType 4 (Canceled), or OrdStatus 4 on a report that is not ExecType 6 (Pending Cancel), or a Order Cancel Reject (35=9). Requests are matched by ClOrdID (11), otherwise to the earliest unanswered request of the order.

Replace to confirmation

From each Order Cancel/Replace Request (35=G) (or 35=AC) to an Execution Report with ExecType 5 (Replaced) or an Order Cancel Reject with 434=2.

Test Request to Heartbeat

From a Test Request (35=1) to the Heartbeat (35=0) from the other side that carries the same TestReqID (112).

p50, p90, p99 and max

Nearest-rank percentiles: the samples are sorted and p is the value at position ceil(p / 100 × n). p50 is the median; with fewer than 100 samples p99 equals the maximum. The mean is in the API output.

Clock

Log timestamp (when the log writer saw each message), SendingTime (52) (when each sender sent it) or TransactTime (60) (when the business event happened, set by each party). A pair is measured only when both messages have the chosen time; the rest are counted as not measured.

Histogram and latency over time

Samples in log-spaced buckets (1, 2.5, 5, 10 and so on, in µs, ms or s), and the median and maximum per interval of the day, placed by the time of the request.

Example from the demo log

These figures are calculated from the demo trading day that the analyzer loads with See it on the demo log, so they match what you see there. In the analyzer every bar and row opens the FIX messages behind it.

On the log clock, half of the 2,037 acknowledgements in the demo day arrive within 1.77 ms and 99% within 10.2 ms; the slowest takes 2.39 s. The mean, 6.28 ms, is 3.5 times the median because a few slow acks pull it up: the percentiles show that most orders are acknowledged quickly and a handful are not.

First fill has a median of 4.90 s because it includes the time orders rest in the book before they trade. Cancels are confirmed in 2.00 ms at the median and 9.43 ms at p99.

On TransactTime (60) the slowest ack is 830.0 ms rather than 2.39 s: each clock measures a different interval, so compare figures on the same clock. On SendingTime (52) the ack p50 is 2.00 ms, because SendingTime in the demo is stamped to the millisecond while the log timestamps carry microseconds. Test Request to Heartbeat (1 sample, 8.80 s) cannot be measured on TransactTime at all: session messages carry no TransactTime (60).

How to read it: what good and bad look like

• Use percentiles, not the average. A handful of slow answers pulls the mean far above what a typical order sees; p50 shows the typical case and p99 the slow tail that users and risk checks notice.
• A p99 far above p50 points to queuing or a slow hop that only some orders take: a busy moment, a garbage collection pause, a risk check on a cold path or a venue that is slow for some symbols. Check the latency over time chart to see whether the slow samples bunch together.
• A maximum far above p99 is usually one event. Click it in the analyzer to open that order and see every message around it.
• First fill latency mixes system time with market time. A limit order that rests for minutes has a long first fill and nothing is wrong; compare first fill only between orders of the same type.
• The log clock measures one host's view: both times are stamped by the machine that wrote the log, so clock skew cannot affect it, but it includes the network both ways and the other side's processing.
• SendingTime (52) and TransactTime (60) are stamped by different parties. The difference between your SendingTime and theirs includes the offset between the two machines' clocks. Negative latencies, or a p50 that changes when you switch clocks, are signs of clock skew rather than of fast systems.
• Resolution limits what you can see. A clock stamped to the millisecond moves in 1 ms steps and cannot show anything faster; check the precision of the times in your log before reading sub-millisecond figures.
• A Pending Cancel (150=6) or Pending Replace (150=E) does not end the measurement. Cancel and replace latency run to the final Canceled or Replaced report, or the reject.

Common causes and fixes

When a figure on this page looks wrong, these pages explain the errors most often behind it and how to fix them.

• SendingTime accuracy problem (373=10)
• Heartbeat timeout / TestRequest
• Too late to cancel (102=0)
• Unknown order (102=1)
• Guide: FIX order lifecycle
• Guide: FIX session layer

For engines: POST a log to the API

The same statistics are available over HTTP for scripts, monitoring jobs and engines. POST a log as text, gzip or a multipart file and get JSON, an HTML report or a plain-text summary back. The request is processed in memory and not stored.

curl --data-binary @fix.log -H "Content-Type: text/plain" "https://fixparser.zagtrader.com/api/v1/analyze?clock=60"

Fields in the JSON response for this page:

• stats.latency.clock: clock used: log, sending or transact (?clock=log, 52 or 60)
• stats.latency.metrics[]: metric, count, p50, p90, p99, max, mean per measurement
• stats.latency.metrics[].histogram[]: lo, hi, label, count
• stats.latency.metrics[].overTime[]: t, p50, max, count per interval
• stats.latency.unmeasured: pairs without a time on the chosen clock

Questions

How do I measure FIX order latency from a log?

Load the log in the analyzer and open the Analytics view. It pairs each New Order Single (35=D) with its first Execution Report and reports p50, p90, p99 and max ack latency, plus first fill, cancel, replace and Test Request to Heartbeat, with a histogram and latency through the day.

Which clock should I use for FIX latency?

The log timestamp when the log was written by one engine that saw both messages: it is one clock, so skew does not apply. SendingTime (52) when you want each side's send time and the hosts are well synchronised. TransactTime (60) when you care about business event times, for example at the venue.

Why are some latencies negative?

On SendingTime (52) or TransactTime (60) the two times come from different machines. If the answering side's clock is behind yours, its time can be earlier than your request. That is clock skew, not a fast answer.

Why use p99 and not the average?

Latency is skewed: most answers are fast and a few are very slow. The average mixes the two and describes neither. p50 shows the typical order, p99 the slowest 1%, and the maximum the single worst case.

What does the ack measure exactly?

The time from the new order to the first Execution Report for that order, normally ExecType 0 (New) or A (Pending New). If the first report is a reject or a fill, that report is used, because it is the first answer the sender received.

Can I get latency from the API?

Yes. POST the log to /api/v1/analyze with clock=log, 52 or 60. The JSON has stats.latency.metrics with count, p50, p90, p99, max and mean for each measurement.

Reference

More of what the analyzer measures

• Message rate: Messages per second, peak second and busiest minute, mix by MsgType and category, inbound and outbound.
• Order outcomes: How every order ended: filled, partly filled, cancelled, expired, rejected or open, with fill, reject and cancel rates.
• Execution analysis: Execution Reports by ExecType (150), partial and full fills, and the fill-size distribution from LastQty (32).
• Trading activity: Volume and traded value per symbol and currency, side, order type, time in force, venues, order-to-trade and cancel-to-fill.
• Reject analysis: SessionRejectReason, OrdRejReason, CxlRejReason and BusinessRejectReason ranked, Text (58) grouped, CheckSum and BodyLength errors.
• Session health: Per session: heartbeats, test requests, sequence gaps, resends and gap fills, resets, logons, logouts and the longest silence.
• FIX Log Analyzer: every statistic, how privacy works and how to start