You cannot fix latency you cannot locate. Linux will stamp every received packet with the time the kernel took it from the driver (SO_TIMESTAMPNS, delivered as ancillary data with recvmsg). With a send-time timestamp inside the payload, one receive gives you two numbers per packet: send -> kernel rx stamp the sender's stack + loopback delivery kernel stamp -> user how long the packet sat in the socket queue before your code got it: the WAIT A sender thread emits 20k packets 50 us apart; the receiver is either blocking in recvmsg or busy-polling.
$ git clone https://github.com/adit4443ya/debug_labs.git && cd debug_labs
$ (cd systems && ./build.sh) -> bin/05_timestamps [spin]
$ Receiver pins to CPU 2, sender to CPU 4. Port 40004.
$ ./bin/05_timestamps
receiver: blocking recvmsg (20000 packets, 50 us apart)
label min p50 p90 p99 p99.9 max mean (ns)
send -> kernel rx stamp 2261 5228 6949 8762 27931 59774 5244.2
kernel stamp -> user 4871 16971 98493 1206926 2763328 3334524 61065.3$ ./bin/05_timestamps spin
receiver: busy-poll (MSG_DONTWAIT loop) (20000 packets, 50 us apart)
send -> kernel rx stamp 1889 1989 2415 5874 14225 63690 2180.8
kernel stamp -> user 2312 2762 3340 7282 12925 48161 2960.4- The wait, blocking: p50 17 us, p90 98 us, p99 1.2 ms, max 3.3 ms. With a packet every 50 us the receiver keeps falling asleep and being woken; a wake-up that lands badly (idle state exit, a scheduler tick, the sender thread's own usleep timer sharing the timer wheel) leaves packets queued for hundreds of microseconds. Nothing in the network stack was slow; the packet was READY and nobody was there to take it. A profile of this program would show the receiver idle. - The wait, spinning: p50 2.8 us, p99 7.3 us, max 48 us. That is the floor for "kernel queued it -> recvmsg returned" with the copy and the ancillary data. 6x better median, 165x better p99. - send -> stamp also improved (5.2 -> 2.0 us). On loopback the sender's CPU runs the receive-side processing in the same softirq, and with a sleeping receiver that path includes the work of waking it; an idle receiving core also responds more slowly to everything. Verify with `perf sched` / ftrace sched_wakeup events (root) if you need the breakdown; the point here is that the stamp separates "stack" from "wait" without guessing.
Application-level timing (before and after recv) cannot distinguish a slow network from a slow receiver. Kernel timestamps can, at a few hundred ns of cost per packet. NIC hardware timestamps (SO_TIMESTAMPING with SOF_TIMESTAMPING_RX_HARDWARE, PTP-synchronized) extend the same idea to the wire: then you know arrival-on-wire -> driver -> stack -> socket -> user, per packet, in production, all the time. Every serious feed handler records these and alerts on the percentiles.
P1. Instrument the path, do not infer it: kernel (and NIC) receive stamps plus a timestamp in the payload give per-stage latency for free. P2. On a latency-critical receiver, the dominant cost is the wait, and the fix is not to wait (spin on a dedicated core), lab 03. P3. Report the wait as p50/p99/max over a long run under realistic packet rates; a mean of 61 us here hides a 3.3 ms worst case.
1. Change the sender's spacing to 5 us and to 500 us: the blocking receiver's wait gets worse at LOWER rates (it sleeps more deeply). 2. Use SO_TIMESTAMPING with SOF_TIMESTAMPING_TX_SOFTWARE on the sender to get a transmit stamp too, and split send -> stamp into "sendto call -> driver" and "driver -> receive". 3. Run the spinning receiver with an unpinned, busy machine (compile something in another terminal): watch p99 climb; then pin to an otherwise idle core. ============================================================
#include "../tools/bench.h"
#include <arpa/inet.h>
#include <errno.h>
#include <pthread.h>
#include <sys/socket.h>
#include <linux/net_tstamp.h>
#include <unistd.h>
#define PKTS 20000
static uint64_t realtime_ns(void) { struct timespec ts; clock_gettime(CLOCK_REALTIME, &ts); return (uint64_t)ts.tv_sec * 1000000000ull + ts.tv_nsec; }
static void *sender(void *arg) {
bench_pin(4);
int fd = socket(AF_INET, SOCK_DGRAM, 0);
struct sockaddr_in dst = { .sin_family = AF_INET, .sin_port = htons(40004), .sin_addr.s_addr = htonl(INADDR_LOOPBACK) };
for (int i = 0; i < PKTS; i++) { uint64_t t = realtime_ns(); sendto(fd, &t, sizeof t, 0, (struct sockaddr *)&dst, sizeof dst); usleep(50); }
(void)arg; return NULL;
}
int main(int argc, char **argv) {
int spin = argc > 1 && !strcmp(argv[1], "spin");
bench_pin(2);
int fd = socket(AF_INET, SOCK_DGRAM, 0), on = 1;
struct sockaddr_in a = { .sin_family = AF_INET, .sin_port = htons(40004), .sin_addr.s_addr = htonl(INADDR_LOOPBACK) };
if (bind(fd, (struct sockaddr *)&a, sizeof a)) { perror("bind"); return 1; }
if (setsockopt(fd, SOL_SOCKET, SO_TIMESTAMPNS, &on, sizeof on)) { perror("SO_TIMESTAMPNS"); return 1; }
pthread_t th; pthread_create(&th, NULL, sender, NULL);
uint64_t *send2kern = malloc(PKTS * 8), *kern2user = malloc(PKTS * 8); int n = 0;
for (int i = 0; i < PKTS; i++) {
uint64_t payload; char cbuf[256]; struct iovec iov = { &payload, sizeof payload };
struct msghdr msg = { .msg_iov = &iov, .msg_iovlen = 1, .msg_control = cbuf, .msg_controllen = sizeof cbuf };
ssize_t r;
if (spin) { while ((r = recvmsg(fd, &msg, MSG_DONTWAIT)) < 0 && errno == EAGAIN) {} } else r = recvmsg(fd, &msg, 0);
uint64_t now = realtime_ns(); if (r < 0) break;
for (struct cmsghdr *c = CMSG_FIRSTHDR(&msg); c; c = CMSG_NXTHDR(&msg, c))
if (c->cmsg_level == SOL_SOCKET && c->cmsg_type == SO_TIMESTAMPNS) {
struct timespec *ts = (struct timespec *)CMSG_DATA(c); uint64_t k = (uint64_t)ts->tv_sec * 1000000000ull + ts->tv_nsec;
send2kern[n] = k - payload; kern2user[n] = now - k; n++;
}
}
pthread_join(th, NULL);
bench_stats a1 = bench_compute(send2kern + 500, n - 500), a2 = bench_compute(kern2user + 500, n - 500);
printf("receiver: %s (%d packets, 50 us apart)\n", spin ? "busy-poll (MSG_DONTWAIT loop)" : "blocking recvmsg", n);
bench_print_header("ns"); bench_print("send -> kernel rx stamp", &a1); bench_print("kernel stamp -> user", &a2);
return 0;
}A lab is done when you can say what it showed on your machine — not when you have read it.
It decides which problems come first, which drills open, which labs you see and how the Learn surface is organised. Change it any time from the switch in the top bar, or press Escape to look around first.