rxrpc: Trace setting of the request-ack flag

Add a tracepoint to log why the request-ack flag is set on an outgoing DATA
packet, allowing debugging as to why.

Signed-off-by: David Howells <dhowells@redhat.com>
cc: Marc Dionne <marc.dionne@auristor.com>
cc: linux-afs@lists.infradead.org

2 files changed, 59 insertions, 9 deletions

diff --git a/include/trace/events/rxrpc.h b/include/trace/events/rxrpc.h
index d20bf4aa0204..4c501c660123 100644
--- a/include/trace/events/rxrpc.h
+++ b/include/trace/events/rxrpc.h
@@ -242,6 +242,16 @@
 	EM(rxrpc_tx_point_version_keepalive,	"VerKeepalive") \
 	E_(rxrpc_tx_point_version_reply,	"VerReply")
 
+#define rxrpc_req_ack_traces \
+	EM(rxrpc_reqack_ack_lost,		"ACK-LOST  ")	\
+	EM(rxrpc_reqack_already_on,		"ALREADY-ON")	\
+	EM(rxrpc_reqack_more_rtt,		"MORE-RTT  ")	\
+	EM(rxrpc_reqack_no_srv_last,		"NO-SRVLAST")	\
+	EM(rxrpc_reqack_old_rtt,		"OLD-RTT   ")	\
+	EM(rxrpc_reqack_retrans,		"RETRANS   ")	\
+	EM(rxrpc_reqack_slow_start,		"SLOW-START")	\
+	E_(rxrpc_reqack_small_txwin,		"SMALL-TXWN")
+
 /*
  * Generate enums for tracing information.
  */
@@ -263,6 +273,7 @@ enum rxrpc_propose_ack_outcome	{ rxrpc_propose_ack_outcomes } __mode(byte);
 enum rxrpc_propose_ack_trace	{ rxrpc_propose_ack_traces } __mode(byte);
 enum rxrpc_receive_trace	{ rxrpc_receive_traces } __mode(byte);
 enum rxrpc_recvmsg_trace	{ rxrpc_recvmsg_traces } __mode(byte);
+enum rxrpc_req_ack_trace	{ rxrpc_req_ack_traces } __mode(byte);
 enum rxrpc_rtt_rx_trace		{ rxrpc_rtt_rx_traces } __mode(byte);
 enum rxrpc_rtt_tx_trace		{ rxrpc_rtt_tx_traces } __mode(byte);
 enum rxrpc_skb_trace		{ rxrpc_skb_traces } __mode(byte);
@@ -290,6 +301,7 @@ rxrpc_propose_ack_outcomes;
 rxrpc_propose_ack_traces;
 rxrpc_receive_traces;
 rxrpc_recvmsg_traces;
+rxrpc_req_ack_traces;
 rxrpc_rtt_rx_traces;
 rxrpc_rtt_tx_traces;
 rxrpc_skb_traces;
@@ -1395,6 +1407,30 @@ TRACE_EVENT(rxrpc_rx_discard_ack,
 		      __entry->call_ackr_prev)
 	    );
 
+TRACE_EVENT(rxrpc_req_ack,
+	    TP_PROTO(unsigned int call_debug_id, rxrpc_seq_t seq,
+		     enum rxrpc_req_ack_trace why),
+
+	    TP_ARGS(call_debug_id, seq, why),
+
+	    TP_STRUCT__entry(
+		    __field(unsigned int,		call_debug_id	)
+		    __field(rxrpc_seq_t,		seq		)
+		    __field(enum rxrpc_req_ack_trace,	why		)
+			     ),
+
+	    TP_fast_assign(
+		    __entry->call_debug_id = call_debug_id;
+		    __entry->seq = seq;
+		    __entry->why = why;
+			   ),
+
+	    TP_printk("c=%08x q=%08x REQ-%s",
+		      __entry->call_debug_id,
+		      __entry->seq,
+		      __print_symbolic(__entry->why, rxrpc_req_ack_traces))
+	    );
+
 #undef EM
 #undef E_
 #endif /* _TRACE_RXRPC_H */
diff --git a/net/rxrpc/output.c b/net/rxrpc/output.c
index 9683617db704..2922c10bd500 100644
--- a/net/rxrpc/output.c
+++ b/net/rxrpc/output.c
@@ -350,6 +350,7 @@ int rxrpc_send_abort_packet(struct rxrpc_call *call)
 int rxrpc_send_data_packet(struct rxrpc_call *call, struct sk_buff *skb,
 			   bool retrans)
 {
+	enum rxrpc_req_ack_trace why;
 	struct rxrpc_connection *conn = call->conn;
 	struct rxrpc_wire_header whdr;
 	struct rxrpc_skb_priv *sp = rxrpc_skb(skb);
@@ -405,16 +406,29 @@ int rxrpc_send_data_packet(struct rxrpc_call *call, struct sk_buff *skb,
 	 * service call, lest OpenAFS incorrectly send us an ACK with some
 	 * soft-ACKs in it and then never follow up with a proper hard ACK.
 	 */
-	if ((!(sp->hdr.flags & RXRPC_LAST_PACKET) ||
-	     rxrpc_to_server(sp)
-	     ) &&
-	    (test_and_clear_bit(RXRPC_CALL_EV_ACK_LOST, &call->events) ||
-	     retrans ||
-	     call->cong_mode == RXRPC_CALL_SLOW_START ||
-	     (call->peer->rtt_count < 3 && sp->hdr.seq & 1) ||
-	     ktime_before(ktime_add_ms(call->peer->rtt_last_req, 1000),
-			  ktime_get_real())))
+	if (whdr.flags & RXRPC_REQUEST_ACK)
+		why = rxrpc_reqack_already_on;
+	else if ((whdr.flags & RXRPC_LAST_PACKET) && rxrpc_to_client(sp))
+		why = rxrpc_reqack_no_srv_last;
+	else if (test_and_clear_bit(RXRPC_CALL_EV_ACK_LOST, &call->events))
+		why = rxrpc_reqack_ack_lost;
+	else if (retrans)
+		why = rxrpc_reqack_retrans;
+	else if (call->cong_mode == RXRPC_CALL_SLOW_START && call->cong_cwnd <= 2)
+		why = rxrpc_reqack_slow_start;
+	else if (call->tx_winsize <= 2)
+		why = rxrpc_reqack_small_txwin;
+	else if (call->peer->rtt_count < 3 && sp->hdr.seq & 1)
+		why = rxrpc_reqack_more_rtt;
+	else if (ktime_before(ktime_add_ms(call->peer->rtt_last_req, 1000), ktime_get_real()))
+		why = rxrpc_reqack_old_rtt;
+	else
+		goto dont_set_request_ack;
+
+	trace_rxrpc_req_ack(call->debug_id, sp->hdr.seq, why);
+	if (why != rxrpc_reqack_no_srv_last)
 		whdr.flags |= RXRPC_REQUEST_ACK;
+dont_set_request_ack:
 
 	if (IS_ENABLED(CONFIG_AF_RXRPC_INJECT_LOSS)) {
 		static int lose;