description: "Why the mean hides your worst latency, how to record percentiles without allocating, and how a test loop can under-report a one-second freeze by a factor of 900. Runnable C#."
tags: csharp, dotnet, performance, fintech
series: "Low-Latency Trading Infrastructure in C#"
"Sub-millisecond" is the most common number in trading software marketing, mine included. It is usually true and it usually answers a question nobody asked. The interesting questions are: sub-millisecond for which interval, measured with which clock, and what happens in the worst one request in a thousand?
Part 1 of this series ended with a quick benchmark loop. This part is about doing that properly: a clock you can trust, a histogram that costs nothing to record into, and the measurement mistake that makes almost every home-made latency test look better than reality.
Disclosure: I build trading infrastructure at HFT Software, including HFT Forex Copier and HFT Arbitrage Platform. Both are judged by their tails, not their averages, which is why I care.
Everything below is plain C# 7 with no packages and runs on .NET Framework 4.8 and current .NET.
Use the right clock
DateTime.UtcNow is a wall clock. It can jump when the system time is adjusted, and on Windows its effective resolution has historically been far coarser than the code you are timing. It is the right tool for timestamps you show to humans and the wrong tool for intervals.
Stopwatch wraps the monotonic high-resolution counter of the platform. Use the static GetTimestamp() so that timing does not allocate a Stopwatch object per measurement:
using System;
using System.Diagnostics;
using System.Globalization;
using System.Text;
public static class Clock
{
static readonly double NsPerTick = 1e9 / Stopwatch.Frequency;
public static long Now() { return Stopwatch.GetTimestamp(); }
public static long ElapsedNs(long startTicks)
{
return (long)((Stopwatch.GetTimestamp() - startTicks) * NsPerTick);
}
}
Check Stopwatch.IsHighResolution once at start-up. If it is false you are on a fallback timer and nothing below means much.
One boundary to respect: a monotonic counter is only comparable with itself on the same machine. The moment you subtract a timestamp taken on another host, you are measuring clock synchronisation error, which over the public Internet is milliseconds. I come back to this at the end.
Stop averaging
Latency distributions are not bell curves. They have a tight body and a long tail, and the tail is where timeouts, missed fills and angry users live. The mean blends the two into a number that describes neither. Report percentiles: p50 for the typical case, p99 and p99.9 for the tail, and the maximum.
Keeping every sample in a list to sort later works in a benchmark and is a bad idea in a live system, because it allocates and grows. A histogram with logarithmic buckets gives you percentiles at a fixed memory cost and a known relative error. This one uses 32 linear sub-buckets per power of two, which keeps the error around 3%:
// Log-linear buckets: 32 linear sub-buckets per power of two, so any value is
// recorded with a relative error of about 3%. Record() never allocates.
public sealed class LatencyHistogram
{
const int SubBits = 5;
const int SubCount = 1 << SubBits;
readonly long[] _counts = new long[64 * SubCount];
long _total, _max;
double _sum;
public long Count { get { return _total; } }
public long Max { get { return _max; } }
public double Mean { get { return _total == 0 ? 0 : _sum / _total; } }
public void Record(long valueNs)
{
if (valueNs < 0) valueNs = 0;
_counts[IndexOf(valueNs)]++;
_total++;
_sum += valueNs;
if (valueNs > _max) _max = valueNs;
}
public long Percentile(double p)
{
long rank = (long)Math.Ceiling(p / 100.0 * _total - 1e-9);
if (rank < 1) rank = 1;
long seen = 0;
for (int i = 0; i < _counts.Length; i++)
{
seen += _counts[i];
if (seen >= rank) return Math.Min(UpperBoundOf(i), _max);
}
return _max;
}
static int IndexOf(long v)
{
if (v < SubCount) return (int)v;
int msb = 0;
for (long t = v; (t >>= 1) != 0;) msb++; // on .NET Core 3.0+ use BitOperations.Log2
int shift = msb - SubBits;
return ((shift + 1) << SubBits) + (int)((v >> shift) - SubCount);
}
static long UpperBoundOf(int index)
{
if (index < SubCount) return index;
int shift = (index >> SubBits) - 1;
long sub = (index & (SubCount - 1)) + SubCount;
return ((sub + 1) << shift) - 1;
}
// unitNs: 1e3 to print microseconds, 1e6 to print milliseconds
public string Summary(string name, double unitNs, string unit)
{
return string.Format(CultureInfo.InvariantCulture,
"{0,-10} mean={1,8:F2} p50={2,8:F2} p90={3,8:F2} p99={4,8:F2} p99.9={5,8:F2} max={6,8:F2} {7}",
name, Mean / unitNs, Percentile(50) / unitNs, Percentile(90) / unitNs,
Percentile(99) / unitNs, Percentile(99.9) / unitNs, _max / unitNs, unit);
}
}
Record is an array increment and two additions. It never allocates, so you can leave it in production code paths. This is a deliberately small cousin of HdrHistogram, which you should use if you need configurable precision, merging or serialisation.
One consequence of bucketing: reported percentiles are bucket upper bounds. A true 1.00 ms shows up as 1.02 ms. That is the 3% at work, not a bug.
Measuring real code
Here is the pattern for timing a piece of code, using a deliberately allocation-heavy workload that resembles a naive string-based message parser:
public static class LiveMeasurement
{
public static void Run()
{
var hist = new LatencyHistogram();
var sb = new StringBuilder();
const int N = 200000;
for (int i = 0; i < 20000; i++) Work(sb, i); // warm-up: JIT, caches
int gen0 = GC.CollectionCount(0), gen2 = GC.CollectionCount(2);
for (int i = 0; i < N; i++)
{
long t0 = Clock.Now();
Work(sb, i);
hist.Record(Clock.ElapsedNs(t0));
}
Console.WriteLine("high resolution clock: " + Stopwatch.IsHighResolution
+ ", tick = " + (1e9 / Stopwatch.Frequency).ToString("F0", CultureInfo.InvariantCulture) + " ns");
Console.WriteLine(hist.Summary("work", 1e3, "us"));
Console.WriteLine("gen0 collections: " + (GC.CollectionCount(0) - gen0)
+ ", gen2 collections: " + (GC.CollectionCount(2) - gen2));
}
// Deliberately allocation-heavy, like a string-based message builder.
static int Work(StringBuilder sb, int i)
{
sb.Length = 0;
sb.Append("35=D|11=ORD-").Append(i).Append("|55=EUR/USD|54=1|38=100000|40=1|59=3|");
string s = sb.ToString();
string[] parts = s.Split('|');
return parts.Length;
}
}
I am not going to print my numbers, because they describe my machine and not yours. Run it. The shape you will see is the same everywhere: the mean and the median sit close together, p99.9 is an order of magnitude above them, and the maximum is one or two orders above that. Then look at the gen0 count. A large part of that tail is the garbage collector, and the mean told you nothing about it.
Three habits that make these numbers honest:
- Warm up before measuring. The first thousand iterations include JIT compilation and cold caches.
- Print GC collection counts next to every latency result. A tail without its GC count is half a measurement.
- Measure in a Release build, without a debugger attached.
Coordinated omission: how a test loop hides a one-second freeze
Now the mistake that matters most. Gil Tene named it coordinated omission, and nearly every hand-written load test commits it.
A typical test sends a request, waits for the reply, records the time, and sends the next one. Suppose the system freezes for a full second. The test is blocked inside that one request, so it records one slow sample. The hundred requests it should have sent during that second are never sent. When the freeze ends, the loop resumes and records fast samples again. The test has coordinated with the system to omit exactly the measurements that would have looked bad.
A real client does not wait politely. Orders, ticks and user clicks arrive on their own schedule, and every one that arrives during the freeze experiences it.
This is easy to demonstrate without any real waiting, by simulating the system in virtual time. The plan is one request every 10 ms for ten seconds. The system answers in 1 ms, except that five seconds in it freezes for one second. We record each request twice: from the moment it was actually sent, and from the moment it was supposed to be sent.
public static class CoordinatedOmission
{
public static void Run()
{
const long Ms = 1000000; // nanoseconds in a millisecond
const long interval = 10 * Ms; // plan: one request every 10 ms (100 per second)
const long service = 1 * Ms; // the system normally answers in 1 ms
const long stallAt = 5000 * Ms; // five seconds in, it freezes...
const long stall = 1000 * Ms; // ...for one second
const int requests = 1000; // ten seconds of load
var naive = new LatencyHistogram();
var corrected = new LatencyHistogram();
long freeAt = 0;
bool stalled = false;
for (int i = 0; i < requests; i++)
{
long intended = i * interval; // when the request SHOULD have been sent
long start = Math.Max(intended, freeAt); // a blocking tester cannot send earlier
long cost = service;
if (!stalled && start >= stallAt) { cost += stall; stalled = true; }
long finish = start + cost;
freeAt = finish;
naive.Record(finish - start); // what most test loops measure
corrected.Record(finish - intended); // what a real client experiences
}
Console.WriteLine(naive.Summary("naive", 1e6, "ms"));
Console.WriteLine(corrected.Summary("corrected", 1e6, "ms"));
}
}
public static class Program
{
public static void Main(string[] args)
{
if (args.Length > 0 && args[0] == "live") LiveMeasurement.Run();
else CoordinatedOmission.Run();
}
}
The simulation is deterministic, so you will get exactly this output:
naive mean= 2.00 p50= 1.02 p90= 1.02 p99= 1.02 p99.9= 1.02 max= 1001.00 ms
corrected mean= 57.06 p50= 1.02 p90= 102.76 p99= 922.75 p99.9= 1001.00 max= 1001.00 ms
Same system, same second of trouble, two very different reports:
- The naive measurement says p99.9 is 1 ms. One sample in a thousand was slow, and it only shows up as the maximum.
- The corrected measurement says p90 is about 100 ms and p99 is over 900 ms. In fact 112 of the 1,000 requests were delayed, because the backlog that built up during the freeze took time to drain.
- The naive p99 is low by a factor of roughly 900. Even the means differ by a factor of 28: 2 ms against 57 ms.
The fix is in the last line of the loop: measure from the intended send time, not the actual one. If your load generator cannot do that, it is measuring its own politeness.
What this means for a trading path
In an order path the same discipline looks like this:
- Decide which interval you are quoting. Time inside your own process, from event detected to bytes written to the socket, is one thing. Time from the master fill to the follower fill is another, and it is dominated by the network and the receiving broker. I split that second interval into six measurable components in a recent working paper, Trade Replication Latency in Retail Foreign Exchange, together with a reporting checklist.
- Use
Stopwatchtimestamps for everything that happens on one host. For anything that crosses hosts, use the broker's own timestamps (52and60in FIX) and state the clock error you are living with. - Record into a histogram on the live path, not only in the lab. Market open and news releases are when the tail appears.
- Feed the test at a fixed rate that does not depend on responses, or correct for it as above.
If you want to see what such a breakdown looks like from the user side, our interactive copier simulator shows copier time and round trip separately for local and cloud routing. For why a few milliseconds decide whether a strategy exists at all, the numbers in our latency arbitrage software guide are a good illustration. And FIX API Terminal has a sober page on what low latency FIX trading does and does not depend on: mostly the broker, the network and where you host.
Checklist
-
Stopwatch.GetTimestamp()for intervals, neverDateTime. - Never compare monotonic timestamps across machines.
- Warm up, Release build, no debugger.
- Histogram, not a list. Percentiles, not the mean.
- Always report p99, p99.9, max and the GC counts together.
- Drive load at a fixed rate and measure from the intended send time.
- Say which interval the number covers.
I am Sergiy Lutsak (I also publish as Sergey Luts). I have been building high-frequency trading systems since 2000. More about my work: author page.
This article is about software engineering. It is not investment advice, and trading leveraged products carries a high risk of loss.
Top comments (0)