netstacklat: Exclude TCP reads for HOL blocked segments

The 'tcp-socket-read' currently reports the latency for the skb
containing the last TCP segment read from the socket. However, this
segment might have been head of line (HOL) blocked by a previous
segment missing. In this case, netstacklat's reported latency will
include HOL blocking periods that is dependent on external
factors (such as network packet loss, and network latency impacts
retransmission time). As netstacklat is primarily intended to identify
issues within the local host (in the network stack or receiving
applications), filter out any socket reads were the last read SKB
might have experienced HOL-blocking.

To exclude HOL-blocked reads, track whenever a TCP segment arrives
out-of-order (ooo), i.e. ahead of the expected next sequence. These
segments are kept in a separate ooo-queue and later merged back into
the socket receive queue once the missing segment gap has been
filled. The ooo-segments are therefore the only segments that may
experience HOL blocking (as non ooo-segments are immediately added to
the socket receive queue). Specifically, track the right edge (the
maximum) of the ooo sequence range. If the final byte of any socket
read is lower than right edge of the ooo sequence range, filter it out
as potentially HOL blocked. If the last read byte is ahead of the
ooo-range, the last byte must have been read from a segment that
arrived in-order and therefore haven't experienced HOL-blocking, so
it's safe to include the latency measurement. Furthermore, also
invalidate the ooo-range when the last read byte is ahead to prevent
an old ooo-range value sticking around until the sequence number wraps
around.

There are some scenarios that may cause this ooo-filtering to fail.
- If the program is started in the middle of an ongoing flow, there
  may be ooo segments that arrived before we could record them in the
  the tracked ooo-range. This may cause the latency for some initial
  HOL-blocked reads to be reported.

- If multiple reads are done to the socket concurrently, we may not
  correctly track the last read byte. The kernel does not keep a lock
  on the TCP socket at the time our hooked function
  tcp_recv_timestamp() runs. If two reads are done in parallel, it's
  therefore possible that for both reads we will check the last read
  byte (tcp_sock.copied_seq) after the second read has updated it. We
  may then incorrectly conclude that the first read was ahead of the
  ooo-range when it was not, and record its latency when we should
  have excluded it. In practice I belive this issue should be quite
  rare, as most applications will probably not attempt to perform
  multiple concurrent reads to a single connected TCP socket in
  parallel (as then you cannot know which part of the payload the
  parallel reads will return).

- The tracked ooo-range may concurrently be updated at
  tcp_data_queue_ofo() and and tcp_recv_timestamp(), leading to
  inconsitent state.

The last of these issue will be addressed in a later commit that adds
bpf spin locks.

Signed-off-by: Simon Sundberg <simon.sundberg@kau.se>

Author: simosund

headers/vmlinux/vmlinux_net.h

@@ -161,6 +161,35 @@ struct sk_buff {
 	struct skb_ext *extensions;
 };
 
+struct tcp_skb_cb {
+	__u32 seq;
+	__u32 end_seq;
+	union {
+		struct {
+			u16 tcp_gso_segs;
+			u16 tcp_gso_size;
+		};
+	};
+	__u8 tcp_flags;
+	__u8 sacked;
+	__u8 ip_dsfield;
+	__u8 txstamp_ack : 1;
+	__u8 eor : 1;
+	__u8 has_rxtstamp : 1;
+	__u8 unused : 5;
+	__u32 ack_seq;
+	union {
+		struct {
+			__u32 is_app_limited : 1;
+			__u32 delivered_ce : 20;
+			__u32 unused : 11;
+			__u32 delivered;
+			u64 first_tx_mstamp;
+			u64 delivered_mstamp;
+		} tx;
+	};
+};
+
 struct nf_conn {
 	unsigned long status;
 };
@@ -202,4 +231,51 @@ struct sock {
 	u32 sk_rx_dst_cookie;
 };
 
+struct inet_sock {
+	struct sock sk;
+};
+
+struct inet_connection_sock {
+	struct inet_sock icsk_inet;
+};
+
+struct tcp_sock {
+	struct inet_connection_sock inet_conn;
+	__u8 __cacheline_group_begin__tcp_sock_read_tx[0];
+	u32 max_window;
+	u32 rcv_ssthresh;
+	u32 reordering;
+	u32 notsent_lowat;
+	u16 gso_segs;
+	struct sk_buff *lost_skb_hint;
+	struct sk_buff *retransmit_skb_hint;
+	__u8 __cacheline_group_end__tcp_sock_read_tx[0];
+	__u8 __cacheline_group_begin__tcp_sock_read_txrx[0];
+	u32 tsoffset;
+	u32 snd_wnd;
+	u32 mss_cache;
+	u32 snd_cwnd;
+	u32 prr_out;
+	u32 lost_out;
+	u32 sacked_out;
+	u16 tcp_header_len;
+	u8 scaling_ratio;
+	u8 chrono_type : 2;
+	u8 repair : 1;
+	u8 tcp_usec_ts : 1;
+	u8 is_sack_reneg : 1;
+	u8 is_cwnd_limited : 1;
+	__u8 __cacheline_group_end__tcp_sock_read_txrx[0];
+	__u8 __cacheline_group_begin__tcp_sock_read_rx[0];
+	u32 copied_seq;
+	u32 rcv_tstamp;
+	u32 snd_wl1;
+	u32 tlp_high_seq;
+	u32 rttvar_us;
+	u32 retrans_out;
+	u16 advmss;
+	u16 urg_data;
+	u32 lost;
+};
+
 #endif /* __VMLINUX_NET_H__ */

netstacklat/netstacklat.bpf.c

@@ -11,6 +11,10 @@
 
 #define READ_ONCE(x) (*(volatile typeof(x) *)&(x))
 
+// Mimic macros from /include/net/tcp.h
+#define tcp_sk(ptr) container_of(ptr, struct tcp_sock, inet_conn.icsk_inet.sk)
+#define TCP_SKB_CB(__skb)	((struct tcp_skb_cb *)&((__skb)->cb[0]))
+
 char LICENSE[] SEC("license") = "GPL";
 
 
@@ -38,6 +42,12 @@ struct sk_buff___old {
 	__u8 mono_delivery_time: 1;
 } __attribute__((preserve_access_index));
 
+struct tcp_sock_ooo_range {
+	u32 ooo_seq_end;
+	/* indicates if ooo_seq_end is still valid (as 0 can be valid seq) */
+	bool active;
+};
+
 struct {
 	__uint(type, BPF_MAP_TYPE_PERCPU_HASH);
 	__uint(max_entries, HIST_NBUCKETS * NETSTACKLAT_N_HOOKS * 64);
@@ -66,6 +76,22 @@ struct {
 	__type(value, u64);
 } netstack_cgroupfilter SEC(".maps");
 
+struct {
+	__uint(type, BPF_MAP_TYPE_SK_STORAGE);
+	__uint(map_flags, BPF_F_NO_PREALLOC);
+	__type(key, int);
+	__type(value, struct tcp_sock_ooo_range);
+} netstack_tcp_ooo_range SEC(".maps");
+
+/*
+ * Is a < b considering u32 wrap around?
+ * Based on the before() function in /include/net/tcp.h
+ */
+static bool u32_lt(u32 a, u32 b)
+{
+	return (s32)(a - b) < 0;
+}
+
 static u64 *lookup_or_zeroinit_histentry(void *map, const struct hist_key *key)
 {
 	u64 zero = 0;
@@ -328,6 +354,60 @@ static void record_socket_latency(struct sock *sk, struct sk_buff *skb,
 	record_latency_since(tstamp, &key);
 }
 
+static void tcp_update_ooo_range(struct sock *sk, struct sk_buff *skb)
+{
+	struct tcp_sock_ooo_range *tp_ooo_range;
+
+	tp_ooo_range = bpf_sk_storage_get(&netstack_tcp_ooo_range, sk, NULL,
+					  BPF_SK_STORAGE_GET_F_CREATE);
+	if (!tp_ooo_range)
+		return;
+
+	if (tp_ooo_range->active) {
+		if (u32_lt(tp_ooo_range->ooo_seq_end, TCP_SKB_CB(skb)->end_seq))
+			tp_ooo_range->ooo_seq_end = TCP_SKB_CB(skb)->end_seq;
+	} else {
+		tp_ooo_range->ooo_seq_end = TCP_SKB_CB(skb)->end_seq;
+		tp_ooo_range->active = true;
+	}
+
+}
+
+static bool tcp_read_in_ooo_range(struct sock *sk)
+{
+	struct tcp_sock_ooo_range *tp_ooo_range;
+	struct tcp_sock *tp = tcp_sk(sk);
+	u32 last_read_seq;
+	int err;
+
+	tp_ooo_range = bpf_sk_storage_get(&netstack_tcp_ooo_range, sk, NULL, 0);
+	if (!tp_ooo_range)
+                /* no recorded ooo-range for sock, so cannot be in ooo-range */
+		return false;
+
+	if (!tp_ooo_range->active)
+		return false;
+
+	err = bpf_core_read(&last_read_seq, sizeof(last_read_seq), &tp->copied_seq);
+	if (err) {
+		/*
+		 * Shouldn't happen.
+		 * Should probably emit some warning if reading copied_seq
+		 * unexpectedly fails. Assume not in ooo-range to avoid
+		 * systematically filtering out ALL values if this does happen.
+		 */
+		bpf_printk("failed to read tcp_sock->copied_seq: err=%d", err);
+		return false;
+	}
+
+	if (u32_lt(tp_ooo_range->ooo_seq_end, last_read_seq)) {
+		tp_ooo_range->active = false;
+		return false;
+	}  else {
+		return true;
+	}
+}
+
 SEC("fentry/ip_rcv_core")
 int BPF_PROG(netstacklat_ip_rcv_core, struct sk_buff *skb, void *block,
 	     void *tp, void *res, bool compat_mode)
@@ -393,6 +473,11 @@ int BPF_PROG(netstacklat_tcp_recv_timestamp, void *msg, struct sock *sk,
 	     struct scm_timestamping_internal *tss)
 {
 	struct timespec64 *ts = &tss->ts[0];
+
+	/* skip if preceeding sock read ended in ooo-range */
+	if (tcp_read_in_ooo_range(sk))
+		return 0;
+
 	record_socket_latency(sk, NULL,
 			      (ktime_t)ts->tv_sec * NS_PER_S + ts->tv_nsec,
 			      NETSTACKLAT_HOOK_TCP_SOCK_READ);
@@ -407,3 +492,15 @@ int BPF_PROG(netstacklat_skb_consume_udp, struct sock *sk, struct sk_buff *skb,
 			      NETSTACKLAT_HOOK_UDP_SOCK_READ);
 	return 0;
 }
+
+/* This program should also be disabled if tcp-socket-read is disabled */
+SEC("fentry/tcp_data_queue_ofo")
+int BPF_PROG(netstacklat_tcp_data_queue_ofo, struct sock *sk,
+	     struct sk_buff *skb)
+{
+	if (!filter_network(skb, sk))
+		return 0;
+
+	tcp_update_ooo_range(sk, skb);
+	return 0;
+}

netstacklat/netstacklat.c

@@ -258,7 +258,8 @@ static void hook_to_progs(struct hook_prog_collection *progs,
 		break;
 	case NETSTACKLAT_HOOK_TCP_SOCK_READ:
 		progs->progs[0] = obj->progs.netstacklat_tcp_recv_timestamp;
-		progs->nprogs = 1;
+		progs->progs[1] = obj->progs.netstacklat_tcp_data_queue_ofo;
+		progs->nprogs = 2;
 		break;
 	case NETSTACKLAT_HOOK_UDP_SOCK_READ:
 		progs->progs[0] = obj->progs.netstacklat_skb_consume_udp;