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

diff --git a/include/trace/events/rxrpc.h b/include/trace/events/rxrpc.h
index d20bf4aa0204b7a2f370211cdcc8c9d7f6231a93..4c501c66012306c08a7249cabe5df529c2325e6e 100644 (file)
--- 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 9683617db7049c1e0db8dbd29d6d51b18fada2ad..2922c10bd50006cab1bcb7bdb2a8c32014321e2b 100644 (file)
--- 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;