Life and times of Reliable Tx

For our on-going investigation into the bowels of the networking stack, we looked at the w latency of  the UDP stack, thus the next logical step is TCP. Alot of people turn their nose up at TCP for low latency connections, saying it buffers too much, the latency is too high, your better off using UDP which is great for a certain class of communications, say lossy network game physics. However in finance dropping a few updates is death, and not an option.

Theres  2 general approachs:

1) build a shitty version of TCP ontop of UDP. This is the classic "not invented here" syndrome many developers fall into.
2) use TCP and optimize it for the situation.

In graphics, OpenGL / Direct3D theres a "fast path" for the operations/state/driver that's typically the application bottleneck, which the driver/stack engineers aggressively optimize for. If you change the state such that its no longer on the fast path, it goes though the slower generic code path, produces correct results, but is significantly slower. This approach is to have the best of both worlds, a nice feature rich API but has lightning fast performance for specific use cases.

If we take this philosophy and apply it to the network stack, theres no reason you cant get UDP or better level performance for a specific use case, say short 128B low latency sends but fall back to the more generic/slower code path when it occasionally drops a packet. Resulting in a dam fast, low latency protocol, thats reliable, in-order and most importantly the de-facto standard. And with that...lets put on the rubber gloves and delve into the TCP stack.

First up, lets take a high level view and compare the round trip latency of 128B message of UDP vs TCP. Keep in mind this is all on an un-loaded system, the UDP numbers arent exactly 128B messages but close, so is more a guide than absolute comparison. The trick here, is assuming a 0% packet loss, and an already established TCP connection, then each send() will generate its own TCP segment and thus we can poke data into the payload. Hacky ... yes but easy and does the job for now.

round trip UDP A->B->A

round trip TCP A->B->A

Keep in mind the TCP time scale is x2 the UDP plot and it clocks in around say 35,000ns vs 50,000ns with TCP significantly slower - proving conventional wisdom. Where does the time go? First step is look at the time from application -> NIC on both Tx and Rx sides for Machine A.

UDP sendto() -> Tx descriptor

 

TCP send() -> Tx descriptor

Above plots are on the Tx side of the equation, which is pretty good, not a huge difference considering the UDP vs TCP delta in round trip. So it must be in the Rx logic where TCP has problems?

UDP Rx Intr -> recvfrom()

 

TCP Rx Intr -> recv()

... and we see the Rx is about x2 slower in TCP than UDP, around 2,500ns vs 1,200ns. Not sure whats going on there, obviously related to ACKing each TCP segment its received, but x2 slower ? we can do better for this use case.

Comparing the round trip latency, we are missing about 15,000ns. Machine A is say, a generous 3,000ns so where did 12,000ns go? Onto Machine B. Remember Machine A NIC is directly wired to the SouthBridge vs Machine B has to go via PCIexpress,  thus the latency differences between the machines.

UDP Machine B Rx Intr -> recvfrom()

Machine B TCP Rx Intr -> recv()

On the Rx side its kind of interesting, having a peek almost exactly on 5,000ns is a bit suspicious, yet its slightly faster than UDP - which is ... a little strange. Then a large chunk, over half the transfers around 8,000ns, so another say 3,000ns or so just for Machine B Rx.

Machine B UDP sendto() -> Tx descriptor

Machine B send() -> Tx Descriptor

As with Machine A, the Tx side is fairly consistent with UDP, even to the point of peeks roughly of the same pitch, if slightly translated. Its interesting TCP is somehow slightly faster to hit the NIC -likely differences in datasize.

So we have accounted for a bit over half of the time delta between TCP vs UDP, but where did the rest of the time go? hardware ? seems unlikely. More likely is the UDP vs TCP test data is different enough? Or maybe after many kernel and driver rebuilds the settings are slightly different?

In anycase its surprusing how close the performance is for small sends. Next task is to look into TCP Rx side and see why its not competitive with UDP.

kernel scheduler

The double peek in the Rx -> recvfrom() specifically the kernel -> userland switch looked suspiciously like some sort of core/hardware interaction. So, what happens if we change the # cores. Its really simple to do, just add maxcpus=0 to the kernel boot command. And thus the following plots are generated

 2 Core sendto() -> Tx Desc

 1 Core sendto() -> Tx Desc

Which is kind of interesting, not sure how/why the 1 Core sendto() has quite a few sample points < 1,000ns where the 2 Core version has none, other than that nothing too exciting.

 2 Core Rx Intr -> recvfrom()

 1 Core Rx Intr -> recvfrom()

OTOH receive shows quite a substantial change and as we suspected, it goes from a double peek, to a single peek assumed to be kernel -> userland signaling behaviour.  And ...

2 Core udp finish kernel space -> userspace recvfrom()

 1 Core udp finish kernel space -> userspace recvfrom()

... the plots speak for them self. Strangely, adding cores in some cases increases latency (the 2nd peek),. No idea whats going on, but keep in mind this is a blocking recvfrom() call so its obviously related to how linux scheduler deals with signals.

Live and times of an Rx packet

To complete the picture we need to look at the Rx packet flow, from when linux receives the Rx interrupt to when the user gets the packet from recvfrom(). First up is the high level view, total time from interrupt acknowledge -> recvfrom().

intr ack -> recvfrom()

And it looks fairly similar to our other plots. This has NAPI disabled and separate Rx/Tx handlers, its interesting that using NAPI the latency goes lower(18,000ns) and higher(35,000ns) presumably luck of the draw when polling @ 300Hz (softirq).

Whan happens after linux receives the irq? the network drivers irq hander is invoked where it acknowedges and clears the interrupt. Nothing particuarly interesting yet does take quite a bit of time doing... something? L1/L2 miss reloads? or just latency of reading registers? not sure. Plot is below, around 600ns or so

irq vector -> driver Rx clear

After the intr has been cleared, the driver reads in the Rx descriptors and uses the CPU to copy the packet (from device DMA ring buffer) onto the usual socket RECV buffer.This (RECV) buffer is the one people usually talk about when discussing sockets.

 

device buffer -> socket buffer copy

As you can see (above) the histogram is a bit weird, a clear chunk followed by this longtail of stuff. Guessing this is partially ddr fetch latency, atleast the 1000ns part as its only copying 128B + UDP + IP + Ethernet - not much. Also destination mem address might not be aligned correctly to enable write combining, so its doing a RMW + miss on the source fetch, hope not but its an old x86 processor.The flat 2500ns might be unmapping the packets DMA area, where some sort of kernel / pci functions are at work. On a side note, not sure why it unmapps it, and then re-mapps it when the Rx descriptor is free and ready, surely its not for security?

After the payload has been copied, it does IP processing / sanity checking  which is a very small profile so no plot included - it caches all ip/device/socket  info from the previous packet.

 

  

netfilter PRE_ROUTING

Once IP processing is done its off to the netfilter. PRE_ROUTING is quite minimal (above) does nothing - no rules are defined.

 

netfiler LOCAL_IN

And the same for LOCAL_IN (above) does basically nothing too - no rules are defined.

udp processing

Finally UDP processing(above) things get interesting. Firstly the spread on the plot is quite large, so somethings going on there. The really interesting part is the height - probably hard to see, but theres is a 100% column is time bin 0. E.g. most of the time, udp processing is extremely low, then occasionally it does *something*. Not sure what but definitely a case for investigation.

UDP (kernel) -> recvfrom(user)

Finally the packet arrives in userspace(above) which is the source of our 2 peeks in total latency. The reason for this ? not sure, likely related the blocking/signaling behaviour of the blocking recvfrom() call. Possible theory for size and pitch is the softirq timer frequency (300Mhz default). Where a quick tests is to increase/decrease this frequency, rebuild kernel, run, test and check the result.

Rx latency summary

Its difficult to summarize each module with a single digit as the stdev for each component can vary significantly, however the above is a rough guide for a non-napi configured driver and stack on 2.6.30.10. Its really hard to reproduce the exact numbers, just booting the stock arch-linux distro kernel, which is the source .config file for this 2.6.30.10 kernel shows a wildly different profile. Or reloading the Network driver to many times causes weirdness, such is life when theres a metric ton of code running.

Line count on C files for linux-2.6.30.10/net clocks in at around 912K LOC. net/ipv4 clocks in 128K LOC ...  obviously Ethernet+IP/UDP+Intel e1000e is a fraction of that but even 20k LOC is a significant chunk of logic to make tuning at the microsecond level truly a fine art.

The life and Times of a Tx Packet

Finally.. got some time to spend on this. We got a rough high level view last time on where all the time went, so lets dig a bit deeper into the SW stack to find out what is going on. So.... lets get started using a stock kernel 2.6.30.10, build it, install it, run it  and boom the first plot.

Machine A sendto() -> Tx desc

Which is our toplevel latency reference, of around 1500ns or so from the userlevel function call, to the NIC driver incrementing the Tx Descriptor ring. Not bad, and surprisingly quite a bit faster than our previous tests(2000-3000ns). Why this is, I've no idea, but likely slightly different kernel version and build parameters. Other strange thing is the "shadow graph", possible due to increasing the resolution of our histogram bin size (100ns -> 10ns) all timing is based on an old 2.6Ghz Xeon.

Hacking the networking core is a royal pain in the ass, theres no easy module to build, which means rebuilding the kernel and rebooting each time... paaaaaainfully slow dev cycle. But lets start by looking at glibc code, for sendto(), which does basically nothing - invoke a kernel command so first plot is kernel call overhead.

userland -> kernel overhead

Looks around 250ns on average. The double peeks are most likely due to the 2 hardware threads on the machine, so around 700cycles. One side note thats not evident in the plot is, the kernel overhead time drops from about 1200cycles at the start to averaging 700cycles quickly ~ 1000 calls.

The packet then arrives at udp_sendmsg() in the ipv4 udp code, where it does some misc packet header/buffer allocation and a few checks, finds the cached route and acquires a lock on the socket. General house keeping stuff.

kernel socket/packet house keeping

Housekeeping clocks in around the same as the kernel switch, 6-700cycles or about 250ns. After the packets has been checked, its copied into the sockets send buffer - this is what ppl generally think of when discussing socket buffers. Where it it memcpys the packet from userland into kernel space and enbales/maps PCI/DMA access from the NIC.

Userspace -> Kernelspace Packet copy

Histogram is a bit prickly for some reason, possibly due to PCI dma map commands, as the amount of data we:re copying is tiny - 128B and it should be in the L1 and definitely in L2 cache so not sure whats going on there. Its possible the combo of old hardware and un-aligned writes means the CPU is read-modify-write the destination mem cache line, instead of a driect write (no read) thus we pay the latency cost of an uncached memory fetch. Or... its just kernel dma/pci mapping code, not sure.

IP/UDP header write

After the payload is copied, the stack adds the appropriate IP/UDP headers(above) Nothing too interesting here, but is surprising how long it takes, ~150ns which.. is alot. Packet checksums are all offloaded onto the hardware, so its doing something else here.

Now it gets interesting, almost all stock kernel builds have netfilter enabled, to allow packet filter / routing  / firewalls / vpns etc etc - very core usecases for linux. Theres a ton of books and documents on how to use netfilter/ipchains but in our case its entirely pass thru, in fact we should disable netfilter to reduce latency.

netfilter LOCAL passthru

netfilter POST pass thru

As you can see(above) its still quite fast, 80ns or so all up, but think its safe to assume the exchange isnt trying to h4x0r your machine and its all quite un-necessary.

After netfilter approves the packet, its sent to the NIC driver, using another buffering system, qdisc - queuing disciplines. This is MAC level now, typically a single fast priority FIFO per MAC but its completely configurable using the "tc" traffic control command and probably other tools. Qdisc is a powerful system, enabling various buffering, scheduling and filters to be applied but they all add latency, - not particularity helpful  for low latency systems. In fact I intend to completely disable qdisc to reduce latency.

 qdisc packet enqueue

Queing is fairly fast (above) around 130ns or so, the 2nd hump in the histogram is interesting.Guessing its wait time for a atomic lock. Now that our packet is on the queue for eth0, all that's left is for the net scheduler to issue it to the NIC driver. However, there's a nice optimization that after the packet is queued, it immediately attempts to send the packet to the driver, and in this case  usually succeeds The only reason it can fail to immediately send is, if another hardware thread is running the net scheduler thus pushing data to the driver, e.g. we have a small fifo here to avoid dropping packets, but it does add another source of latency.

qdisc queue -> driver xmit

As expected (above), the latency from qdisc queue, to issuing a driver call is  small 100ns or so. Whats interesting is the double spikes, assuming it misses the initial scheduling pass, and hits on the 2nd try.

 NIC driver 1 Tx packet process time

And finally(above) our trusty e1000e NIC driver processing cost, which fills our the Tx descriptor and moves the ring buffer forward. Then frees the packet and is fairly quick to process 400ns. Note, this is the time from driver entry point, to exit point, which is longer than driver entry -> Tx update(below)/hardware hand off, due to cleanup code.

qdisc enqueue -> NIC Tx descriptor write

The question is, if the NIC driver is only taking 3-400ns to kick a Tx descriptor, then the rest of the time must be spent in the  linux kernels networking stack?

 

 sendto() -> the start of NIC driver handoff

Answer -> yes, most of the time is spent in the kernel.. Plot above shows the entire SW latency excluding the NIC driver where the shape matches the first high level plot (green one) except shifted slightly to the left.  This is good as we have quite a few options to reduce the kernels processing time, to make that packet hit the MAC in < 1,000ns!

typical high level Tx hw/sw flow @ 2.6Ghz old Xeon machine

In summary, the above flow chart shows our current latency estimates. We can only guesstimate the hardware latency due to lack of tools but you can clearly see the HW latency is far greater than the software. As  we are using a typical (old) consumer/server hardware layout thats designed for high throughput NOT ultra low latency. Which is why anyone serious about  ultra low latency... has a very different hardware topology :)

nick to nick, whats the time?

The topology of the previous test was NIC -> switch -> NIC and we assumed the switch was causing un-due latency. Turns out this is true, but not to the extent anicipated.

NIC <-> switch <-> NIC fabric time

NIC <-> NIC fabric time

As you can see, ditching the switch gained about 7,000ns, not bad but there`s still 23,000ns going somewhere. First thing to always do is back-of-the-envelope calculation and multiply by two.

GigE throughput is 1e9 bits / second, so on average the frame is say 160B (minus PHY framing) so that's 160 * 8 / 1e9  - roughly 1,280ns to encode one way. We`re doing this x4 (encode->decode->encode->decode) so we`re up to 5,120ns or so to encode the thing, and lets be generous and double it, resulting in around 10,000ns to account for GigE PHY framing. and  other junk, but we`re still missing 13,000ns!

Taking a detour, the 82573L NIC we`ve used so far is... slightly incorrect. Seems I assumed NICx2 on a blade would use the same controller, however this is incorrect. The 82573L NIC we`ve been assuming, is in fact a Intel 82566DC-2 NIC. If we change it to really use the 82573L the picture ain`t pretty.

NIC <-> NIC real intel 82573

And when its compared with using the Intel 82566DC its quite interesting.

NIC <-> NIC Intel 82566DC

Its true the 82573L is about a year older than the 82566DC, 2005 vs 2006 but that alone cant explain the huge 15,000ns or so difference. Digging a bit deeper, there`s significant difference in host interface between the two cards, the 82573L uses PCIe while the 82566DC use`s intels proprietary LCI/GLC bus - its wired directly to the southbridge. Lets use some creative licensing, and assume say 5,000ns is improved hardware design, leaving around 5,000ns each way, spent in the PCIe encode/decode/hub/and largish staging buffers, which conveniently is near our missing 13,000ns number (remember only 1 NIC is on PCIe).

And we have some ideas on where the time has gone:

- 10,000ns for GbE encode/decode/transport

- 10,000ns for PCIe encode/decode/forward/transport.

 - 3,000ns LCI/GLC encode/decode/transport (whats left)

How realistic these guesstimates are I`ve no idea and further digging requires hardware tools which are expensive, thus aren`t available. So we`ll leave it at 23,000ns in the interconnect fabric, and average HW time as 23,000ns / 4 = 5,740ns or so in one direction.

lost in the ether

Ok... so where did that 37,500ns go? I`ve got my suspicions but lets go hack the sauce and get some numbers. First thing to try is any other dials and knobs in the driver, namely:

- disable NAPI

- separate Rx & Tx interrupts

Starting with our baseline from the last post, except using the latest driver from the intel site vs whats in 2.6.30 kernel we get the following plot(below). Did not expect anything major and.. it looks quite similar.

Stock intel 1.1.2 NAPI driver

Next up is to disable NAPI. Resulting in higher CPU loading but potentially lower latency. Plot looks a bit different, but roughly the same, there's some fairly clear changes and the latency increases.. doh.

Disable NAPI

The other builtin knob is, seperate Rx and Tx interrupts, so it uses unique irq`s  per queue instead of shared. Interestingly the histogram`s shape becomes significantly more clear, assuming due to less jitter on interrupt latency.

Disable NAPI, Rx/Tx interrupts separate (+64bx8 header)

Which is all good but has done nothing for total latency, and actually made it worse, so its time to put the rubber gloves on and hack the driver.

While we`re prepping, lets go back and look at whats actually going on. The diagram(left) shows a high level view of the major components we need to test. Namely,

- Machine A Application

- Machine A Kernel + Driver

- Fabric / Ethernet / Hardware

- Machine B Kernel + Driver

- Machine B Application

... and back again.

There`s 2 interesting points in the NIC drive, namely:

- Rx interrupt dispatch

- Tx descriptor write

These events are the first and final contact points between SW and HW. Rx Interrupt dispatch gives a timestamp when the entire sw/os stack is first aware of there is a new UDP packet.

On the other side, Intels network cards use a hardware structure in memory known as a descriptor which contains the location, size and a few other attributes about a raw ethernet frame. To send data onto the network the driver builds this structure in a ring buffer, then advances hardware ring buffers position. This advancement tells the hw theres are new descriptors pending, so it can fetch the descriptor(s) + associated memory and eventually push  onto the physical layer/wire. Essentially the hw/sw contact point is when the driver hands off the packet for HW processing.

Using these two events + time stamps at sendto() and recvfrom() we can re-construct a time profile and also look at HW <-> App latency  The timestamps are stored in a, umm... rather rude and amusing way. We added a 64b x 8 header to every ITCH4 message that almost x2 the message size but makes things easy. In the driver, we simply check the UDP header for our magic port number and if it matches, write out the time stamps in unique 64b header slot. Yeah rather nasty.. but this is an holiday hack project - meh..

Ok all the prep is done, so how does it look? Lets follow a single packet in chronological order. First we send the raw ITCH4 packet + header from A in userland.

Latency from Userland -> NIC (Machine A)

Here(above) we see the time it takes from userland sendto() to the driver updating the Tx descriptor ring - full SW latency of sendto(). After this point, the packet journeys across the network fabric from NIC HW + Switch + NIC HW arriving at Machine B`s NIC.

Latency NIC Rx Interrupt -> User Land (Machine B)

After the packet has been decoded by the NIC, it generates an Rx interrupt on Machine B, telling it, there's some data ready. The above plot shows the time between when the Rx interrupt arrives on the CPU, to recvfrom() call returning in userland - full recvfrom() SW latency. Why are there 2 spikes? its not clear. One possible cause is a packet size threshold causes a split code path, and thus the profile into two bins.

Machine B`s user land code is trivial. It sets a header timestamp, then does sendto() of the exact same packet e.g. echo`ing the packet, resulting in the full SW latency from sendto() to NIC  for Machine B.

sendto() -> Tx descriptor update (Machine B)

Again we see these 2 spikes, which hmm... needs investigation. One other thing to notice is  sendto() latency on MachineB is quite a bit slower than MachineA.

After the packet is at Machine B`s NIC, it goes back to the switch, to MachineA`s NIC and generates an Rx interrupt - full recvfrom() SW latency on Machine A (below)

Rx ISR -> recvfrom() (Machine A)

Which is unusually fast, and also a single profile - hmmm... suspicious. In any case we`ve now got everything to fill in the blanks. Whats troubling is we`re a long way off a total latency of 40,000ns! Its good but also bad. So with a few lines of code we get top level MachineA/B full SW latency plots.

Total SW Latency (Machine A)

Total SW latency (Machine B)

Which is Rx+Tx latency for a single packet, and plotting that number on a histogram. Whats really strange is Machine B is *slower* than Machine A, something rather surprising. One possible latency source is is MachineA has 2 HW threads, while Machine B has 8 HW threads. I'm not familiar enough with the linux scheduling algo to know if this changes the profile, but worth checking out.

.... and doing the math you get a plot(below) for fabric time.

Fabric time (NIC->Switch->NIC)

Which is a huge.. huge... chunk of time, say 30,000ns! The good news is, SW latency is around 10,000ns  which is close(ish) to our throughput number of 3,500ns (x3) so we`re 1/3 thoughput/latency.  Seccond good thing is, the GigE switch is a cheap ass old, second hand thing I bought for $100 - 24port, rack mounted GigE, not bad  given the price but aint cisco. Its Corega which is equivelent to Netgear in Asia, does the job, its cheap but your average LAN dosent need sub 10,000ns latency and so the switch is our prime suspect err...... device of interest.

udp latency baseline

Now that the NIC`s are sorted, we can look into the round trip latency numbers. The guesstimate based on the previous post was around 3450ns, or 3.5us which is ... err.. "slightly" off..

First up we`ll go flat out so A sends as many packets to B, and B tries to relay them back to A. When A gets the packet, its got a send time stamp, so we can log the time delta into a histogram(below)

Sending at full rate

Yes, that{s 200 microsecconds at the end, just a bit longer than 3500ns. What a mess.. Simplifying it down to a serial round trip latency histogram, translates to:

1) A Send
2) B recv
3) B Send back to A
4 A Recv
5) A Next message

So the system is on a minimum work loading thus, should get the minimum round trip latency. We get the following graph(below) which is alot cleaner, even if highly disturbing

Serial Round Trip

As you can see, it clocked in around 100,000ns ! that`s 96550ns longer than expected, and with a razor thin spread.

So whats going on? For one a razor thin profile centered almost exactly on 100,000ns is extremely suspicious of a timer at work. With a little bit of digging, lo and behold there is, called Interrupt Coalescing - in the Intel Network card drivers and generally part of the NAPI. Its purpose is to reduce CPU load by batching interrupts into groups, so there's only 1 interrupt per say 32 packets, thus all 32 packets *may* be processed in that single interrupt handler. Which is fine and great, improves network throughput and a good general all-purpose solution but is killing our low latency system.

On page 19 on Intels "Interrupt Moderation Using GbE Controllers" manual there`s a fantastic graph.

If you check the area circled, its the default parameter setting for intel drivers and looks... around 50,000ns which conveniently (round trip) adds up to what were seeing in our histogram 100,000ns. Thus lets mess with the parameter. First up is changing Machine B to InterruptThrottleRate=8000 (intels old default)

Machine B InterruptThrottleRate=8000

And great, our latency number moves (in the wrong direction) but none the less a very direct correlation. Thus lets disable all throttling on Machine B

Machine B Interrupt Throttle Rate = OFF

And bang, we just reduced the latency by half! Not bad for a one liner. The Spikes are still extremely tall and thin, suggesting theres still a timer element in there. Next up, disable throttling for Machine A too.

Machine A & B Interrupt Throttle Rate = OFF

And finally we have somthing that has a fairly small spread, but not so thin that it looks like a timer, and must be close to our baseline round trip number. App -> Lib -> Kernel -> NIC -> Wire -> Switch -> Wire -> NIC -> Kernel -> Lib -> Bapp and back.

Machine A & B, Interrupt Throttling Rate = OFF

And a close up of what kind of latency we`re getting, calling it at 40,000ns round trip which ... is alot. Yet from the previous experiments 3500ns of that is in the throughput, so where did the rest go?