From 4700c4d80b7bb171f6996016ef121e1508860b42 Mon Sep 17 00:00:00 2001 From: David Howells Date: Wed, 19 Aug 2020 23:29:16 +0100 Subject: rxrpc: Fix loss of RTT samples due to interposed ACK The Rx protocol has a mechanism to help generate RTT samples that works by a client transmitting a REQUESTED-type ACK when it receives a DATA packet that has the REQUEST_ACK flag set. The peer, however, may interpose other ACKs before transmitting the REQUESTED-ACK, as can be seen in the following trace excerpt: rxrpc_tx_data: c=00000044 DATA d0b5ece8:00000001 00000001 q=00000001 fl=07 rxrpc_rx_ack: c=00000044 00000001 PNG r=00000000 f=00000002 p=00000000 n=0 rxrpc_rx_ack: c=00000044 00000002 REQ r=00000001 f=00000002 p=00000001 n=0 ... DATA packet 1 (q=xx) has REQUEST_ACK set (bit 1 of fl=xx). The incoming ping (labelled PNG) hard-acks the request DATA packet (f=xx exceeds the sequence number of the DATA packet), causing it to be discarded from the Tx ring. The ACK that was requested (labelled REQ, r=xx references the serial of the DATA packet) comes after the ping, but the sk_buff holding the timestamp has gone and the RTT sample is lost. This is particularly noticeable on RPC calls used to probe the service offered by the peer. A lot of peers end up with an unknown RTT because we only ever sent a single RPC. This confuses the server rotation algorithm. Fix this by caching the information about the outgoing packet in RTT calculations in the rxrpc_call struct rather than looking in the Tx ring. A four-deep buffer is maintained and both REQUEST_ACK-flagged DATA and PING-ACK transmissions are recorded in there. When the appropriate response ACK is received, the buffer is checked for a match and, if found, an RTT sample is recorded. If a received ACK refers to a packet with a later serial number than an entry in the cache, that entry is presumed lost and the entry is made available to record a new transmission. ACKs types other than REQUESTED-type and PING-type cause any matching sample to be cancelled as they don't necessarily represent a useful measurement. If there's no space in the buffer on ping/data transmission, the sample base is discarded. Fixes: 50235c4b5a2f ("rxrpc: Obtain RTT data by requesting ACKs on DATA packets") Signed-off-by: David Howells --- include/trace/events/rxrpc.h | 27 ++++++++++++++++++++++----- 1 file changed, 22 insertions(+), 5 deletions(-) (limited to 'include/trace') diff --git a/include/trace/events/rxrpc.h b/include/trace/events/rxrpc.h index 059b6e45a028..c33079b986e8 100644 --- a/include/trace/events/rxrpc.h +++ b/include/trace/events/rxrpc.h @@ -138,11 +138,16 @@ enum rxrpc_recvmsg_trace { }; enum rxrpc_rtt_tx_trace { + rxrpc_rtt_tx_cancel, rxrpc_rtt_tx_data, + rxrpc_rtt_tx_no_slot, rxrpc_rtt_tx_ping, }; enum rxrpc_rtt_rx_trace { + rxrpc_rtt_rx_cancel, + rxrpc_rtt_rx_lost, + rxrpc_rtt_rx_obsolete, rxrpc_rtt_rx_ping_response, rxrpc_rtt_rx_requested_ack, }; @@ -339,10 +344,15 @@ enum rxrpc_tx_point { E_(rxrpc_recvmsg_wait, "WAIT") #define rxrpc_rtt_tx_traces \ + EM(rxrpc_rtt_tx_cancel, "CNCE") \ EM(rxrpc_rtt_tx_data, "DATA") \ + EM(rxrpc_rtt_tx_no_slot, "FULL") \ E_(rxrpc_rtt_tx_ping, "PING") #define rxrpc_rtt_rx_traces \ + EM(rxrpc_rtt_rx_cancel, "CNCL") \ + EM(rxrpc_rtt_rx_obsolete, "OBSL") \ + EM(rxrpc_rtt_rx_lost, "LOST") \ EM(rxrpc_rtt_rx_ping_response, "PONG") \ E_(rxrpc_rtt_rx_requested_ack, "RACK") @@ -1087,38 +1097,43 @@ TRACE_EVENT(rxrpc_recvmsg, TRACE_EVENT(rxrpc_rtt_tx, TP_PROTO(struct rxrpc_call *call, enum rxrpc_rtt_tx_trace why, - rxrpc_serial_t send_serial), + int slot, rxrpc_serial_t send_serial), - TP_ARGS(call, why, send_serial), + TP_ARGS(call, why, slot, send_serial), TP_STRUCT__entry( __field(unsigned int, call ) __field(enum rxrpc_rtt_tx_trace, why ) + __field(int, slot ) __field(rxrpc_serial_t, send_serial ) ), TP_fast_assign( __entry->call = call->debug_id; __entry->why = why; + __entry->slot = slot; __entry->send_serial = send_serial; ), - TP_printk("c=%08x %s sr=%08x", + TP_printk("c=%08x [%d] %s sr=%08x", __entry->call, + __entry->slot, __print_symbolic(__entry->why, rxrpc_rtt_tx_traces), __entry->send_serial) ); TRACE_EVENT(rxrpc_rtt_rx, TP_PROTO(struct rxrpc_call *call, enum rxrpc_rtt_rx_trace why, + int slot, rxrpc_serial_t send_serial, rxrpc_serial_t resp_serial, u32 rtt, u32 rto), - TP_ARGS(call, why, send_serial, resp_serial, rtt, rto), + TP_ARGS(call, why, slot, send_serial, resp_serial, rtt, rto), TP_STRUCT__entry( __field(unsigned int, call ) __field(enum rxrpc_rtt_rx_trace, why ) + __field(int, slot ) __field(rxrpc_serial_t, send_serial ) __field(rxrpc_serial_t, resp_serial ) __field(u32, rtt ) @@ -1128,14 +1143,16 @@ TRACE_EVENT(rxrpc_rtt_rx, TP_fast_assign( __entry->call = call->debug_id; __entry->why = why; + __entry->slot = slot; __entry->send_serial = send_serial; __entry->resp_serial = resp_serial; __entry->rtt = rtt; __entry->rto = rto; ), - TP_printk("c=%08x %s sr=%08x rr=%08x rtt=%u rto=%u", + TP_printk("c=%08x [%d] %s sr=%08x rr=%08x rtt=%u rto=%u", __entry->call, + __entry->slot, __print_symbolic(__entry->why, rxrpc_rtt_rx_traces), __entry->send_serial, __entry->resp_serial, -- cgit v1.2.3