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
This commit is contained in:
David Howells 2022-04-05 21:48:48 +01:00
parent c3d96f690a
commit 4d843be56b
2 changed files with 59 additions and 9 deletions

View File

@ -242,6 +242,16 @@
EM(rxrpc_tx_point_version_keepalive, "VerKeepalive") \ EM(rxrpc_tx_point_version_keepalive, "VerKeepalive") \
E_(rxrpc_tx_point_version_reply, "VerReply") 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. * 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_propose_ack_trace { rxrpc_propose_ack_traces } __mode(byte);
enum rxrpc_receive_trace { rxrpc_receive_traces } __mode(byte); enum rxrpc_receive_trace { rxrpc_receive_traces } __mode(byte);
enum rxrpc_recvmsg_trace { rxrpc_recvmsg_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_rx_trace { rxrpc_rtt_rx_traces } __mode(byte);
enum rxrpc_rtt_tx_trace { rxrpc_rtt_tx_traces } __mode(byte); enum rxrpc_rtt_tx_trace { rxrpc_rtt_tx_traces } __mode(byte);
enum rxrpc_skb_trace { rxrpc_skb_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_propose_ack_traces;
rxrpc_receive_traces; rxrpc_receive_traces;
rxrpc_recvmsg_traces; rxrpc_recvmsg_traces;
rxrpc_req_ack_traces;
rxrpc_rtt_rx_traces; rxrpc_rtt_rx_traces;
rxrpc_rtt_tx_traces; rxrpc_rtt_tx_traces;
rxrpc_skb_traces; rxrpc_skb_traces;
@ -1395,6 +1407,30 @@ TRACE_EVENT(rxrpc_rx_discard_ack,
__entry->call_ackr_prev) __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 EM
#undef E_ #undef E_
#endif /* _TRACE_RXRPC_H */ #endif /* _TRACE_RXRPC_H */

View File

@ -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, int rxrpc_send_data_packet(struct rxrpc_call *call, struct sk_buff *skb,
bool retrans) bool retrans)
{ {
enum rxrpc_req_ack_trace why;
struct rxrpc_connection *conn = call->conn; struct rxrpc_connection *conn = call->conn;
struct rxrpc_wire_header whdr; struct rxrpc_wire_header whdr;
struct rxrpc_skb_priv *sp = rxrpc_skb(skb); 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 * 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. * soft-ACKs in it and then never follow up with a proper hard ACK.
*/ */
if ((!(sp->hdr.flags & RXRPC_LAST_PACKET) || if (whdr.flags & RXRPC_REQUEST_ACK)
rxrpc_to_server(sp) why = rxrpc_reqack_already_on;
) && else if ((whdr.flags & RXRPC_LAST_PACKET) && rxrpc_to_client(sp))
(test_and_clear_bit(RXRPC_CALL_EV_ACK_LOST, &call->events) || why = rxrpc_reqack_no_srv_last;
retrans || else if (test_and_clear_bit(RXRPC_CALL_EV_ACK_LOST, &call->events))
call->cong_mode == RXRPC_CALL_SLOW_START || why = rxrpc_reqack_ack_lost;
(call->peer->rtt_count < 3 && sp->hdr.seq & 1) || else if (retrans)
ktime_before(ktime_add_ms(call->peer->rtt_last_req, 1000), why = rxrpc_reqack_retrans;
ktime_get_real()))) 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; whdr.flags |= RXRPC_REQUEST_ACK;
dont_set_request_ack:
if (IS_ENABLED(CONFIG_AF_RXRPC_INJECT_LOSS)) { if (IS_ENABLED(CONFIG_AF_RXRPC_INJECT_LOSS)) {
static int lose; static int lose;