From ba132d841d5637655273c28d30751c8d18ac189b Mon Sep 17 00:00:00 2001 From: David Howells Date: Mon, 29 Jan 2024 13:51:30 +0000 Subject: rxrpc: Record the Tx serial in the rxrpc_txbuf and retransmit trace Each Rx protocol packet contains a per-connection monotonically increasing serial number used to correlate outgoing messages with their replies - something that can be used for RTT calculation. Note this value in the rxrpc_txbuf struct in addition to the wire header and then log it in the rxrpc_retransmit trace for reference. Signed-off-by: David Howells cc: Marc Dionne cc: "David S. Miller" cc: Eric Dumazet cc: Jakub Kicinski cc: Paolo Abeni cc: linux-afs@lists.infradead.org cc: netdev@vger.kernel.org --- include/trace/events/rxrpc.h | 10 +++++++--- 1 file changed, 7 insertions(+), 3 deletions(-) (limited to 'include/trace') diff --git a/include/trace/events/rxrpc.h b/include/trace/events/rxrpc.h index 87b8de9b6c1c..9add56980485 100644 --- a/include/trace/events/rxrpc.h +++ b/include/trace/events/rxrpc.h @@ -1506,25 +1506,29 @@ TRACE_EVENT(rxrpc_drop_ack, ); TRACE_EVENT(rxrpc_retransmit, - TP_PROTO(struct rxrpc_call *call, rxrpc_seq_t seq, s64 expiry), + TP_PROTO(struct rxrpc_call *call, rxrpc_seq_t seq, + rxrpc_serial_t serial, s64 expiry), - TP_ARGS(call, seq, expiry), + TP_ARGS(call, seq, serial, expiry), TP_STRUCT__entry( __field(unsigned int, call) __field(rxrpc_seq_t, seq) + __field(rxrpc_serial_t, serial) __field(s64, expiry) ), TP_fast_assign( __entry->call = call->debug_id; __entry->seq = seq; + __entry->serial = serial; __entry->expiry = expiry; ), - TP_printk("c=%08x q=%x xp=%lld", + TP_printk("c=%08x q=%x r=%x xp=%lld", __entry->call, __entry->seq, + __entry->serial, __entry->expiry) ); -- cgit From 12bdff73a147aebcea8efae2b395ef0c27448909 Mon Sep 17 00:00:00 2001 From: David Howells Date: Mon, 29 Jan 2024 15:01:10 +0000 Subject: rxrpc: Convert rxrpc_txbuf::flags into a mask and don't use atomics Convert the transmission buffer flags into a mask and use | and & rather than bitops functions (atomic ops are not required as only the I/O thread can manipulate them once submitted for transmission). The bottom byte can then correspond directly to the Rx protocol header flags. Signed-off-by: David Howells cc: Marc Dionne cc: "David S. Miller" cc: Eric Dumazet cc: Jakub Kicinski cc: Paolo Abeni cc: linux-afs@lists.infradead.org cc: netdev@vger.kernel.org --- include/trace/events/rxrpc.h | 12 +++++------- 1 file changed, 5 insertions(+), 7 deletions(-) (limited to 'include/trace') diff --git a/include/trace/events/rxrpc.h b/include/trace/events/rxrpc.h index 9add56980485..33888f688325 100644 --- a/include/trace/events/rxrpc.h +++ b/include/trace/events/rxrpc.h @@ -1084,9 +1084,9 @@ TRACE_EVENT(rxrpc_tx_packet, TRACE_EVENT(rxrpc_tx_data, TP_PROTO(struct rxrpc_call *call, rxrpc_seq_t seq, - rxrpc_serial_t serial, u8 flags, bool retrans, bool lose), + rxrpc_serial_t serial, unsigned int flags, bool lose), - TP_ARGS(call, seq, serial, flags, retrans, lose), + TP_ARGS(call, seq, serial, flags, lose), TP_STRUCT__entry( __field(unsigned int, call) @@ -1094,8 +1094,7 @@ TRACE_EVENT(rxrpc_tx_data, __field(rxrpc_serial_t, serial) __field(u32, cid) __field(u32, call_id) - __field(u8, flags) - __field(bool, retrans) + __field(u16, flags) __field(bool, lose) ), @@ -1106,7 +1105,6 @@ TRACE_EVENT(rxrpc_tx_data, __entry->seq = seq; __entry->serial = serial; __entry->flags = flags; - __entry->retrans = retrans; __entry->lose = lose; ), @@ -1116,8 +1114,8 @@ TRACE_EVENT(rxrpc_tx_data, __entry->call_id, __entry->serial, __entry->seq, - __entry->flags, - __entry->retrans ? " *RETRANS*" : "", + __entry->flags & RXRPC_TXBUF_WIRE_FLAGS, + __entry->flags & RXRPC_TXBUF_RESENT ? " *RETRANS*" : "", __entry->lose ? " *LOSE*" : "") ); -- cgit From 17469ae0582aaacad36e8e858f58b86c369f21ef Mon Sep 17 00:00:00 2001 From: David Howells Date: Fri, 26 Jan 2024 16:17:03 +0000 Subject: rxrpc: Fix the names of the fields in the ACK trailer struct From AFS-3.3 a trailer containing extra info was added to the ACK packet format - but AF_RXRPC has the names of some of the fields mixed up compared to other AFS implementations. Rename the struct and the fields to make them match. Signed-off-by: David Howells cc: Marc Dionne cc: "David S. Miller" cc: Eric Dumazet cc: Jakub Kicinski cc: Paolo Abeni cc: linux-afs@lists.infradead.org cc: netdev@vger.kernel.org --- include/trace/events/rxrpc.h | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) (limited to 'include/trace') diff --git a/include/trace/events/rxrpc.h b/include/trace/events/rxrpc.h index 33888f688325..c730cd732348 100644 --- a/include/trace/events/rxrpc.h +++ b/include/trace/events/rxrpc.h @@ -83,7 +83,7 @@ EM(rxrpc_badmsg_bad_abort, "bad-abort") \ EM(rxrpc_badmsg_bad_jumbo, "bad-jumbo") \ EM(rxrpc_badmsg_short_ack, "short-ack") \ - EM(rxrpc_badmsg_short_ack_info, "short-ack-info") \ + EM(rxrpc_badmsg_short_ack_trailer, "short-ack-trailer") \ EM(rxrpc_badmsg_short_hdr, "short-hdr") \ EM(rxrpc_badmsg_unsupported_packet, "unsup-pkt") \ EM(rxrpc_badmsg_zero_call, "zero-call") \ -- cgit From 12a66e77c4999b97a2c2b8f5e4e7533c656cee12 Mon Sep 17 00:00:00 2001 From: David Howells Date: Tue, 30 Jan 2024 20:30:03 +0000 Subject: rxrpc: Differentiate PING ACK transmission traces. There are three points that transmit PING ACKs and all of them use the same trace string. Change two of them to use different strings. Signed-off-by: David Howells cc: Marc Dionne cc: "David S. Miller" cc: Eric Dumazet cc: Jakub Kicinski cc: Paolo Abeni cc: linux-afs@lists.infradead.org cc: netdev@vger.kernel.org --- include/trace/events/rxrpc.h | 2 ++ 1 file changed, 2 insertions(+) (limited to 'include/trace') diff --git a/include/trace/events/rxrpc.h b/include/trace/events/rxrpc.h index c730cd732348..3b726a6c8c42 100644 --- a/include/trace/events/rxrpc.h +++ b/include/trace/events/rxrpc.h @@ -364,11 +364,13 @@ #define rxrpc_propose_ack_traces \ EM(rxrpc_propose_ack_client_tx_end, "ClTxEnd") \ + EM(rxrpc_propose_ack_delayed_ack, "DlydAck") \ EM(rxrpc_propose_ack_input_data, "DataIn ") \ EM(rxrpc_propose_ack_input_data_hole, "DataInH") \ EM(rxrpc_propose_ack_ping_for_keepalive, "KeepAlv") \ EM(rxrpc_propose_ack_ping_for_lost_ack, "LostAck") \ EM(rxrpc_propose_ack_ping_for_lost_reply, "LostRpl") \ + EM(rxrpc_propose_ack_ping_for_0_retrans, "0-Retrn") \ EM(rxrpc_propose_ack_ping_for_old_rtt, "OldRtt ") \ EM(rxrpc_propose_ack_ping_for_params, "Params ") \ EM(rxrpc_propose_ack_ping_for_rtt, "Rtt ") \ -- cgit From 153f90a066dd4a91ef7edc0df3964dd097a5e2a5 Mon Sep 17 00:00:00 2001 From: David Howells Date: Tue, 30 Jan 2024 21:37:16 +0000 Subject: rxrpc: Use ktimes for call timeout tracking and set the timer lazily Track the call timeouts as ktimes rather than jiffies as the latter's granularity is too high and only set the timer at the end of the event handling function. Signed-off-by: David Howells cc: Marc Dionne cc: "David S. Miller" cc: Eric Dumazet cc: Jakub Kicinski cc: Paolo Abeni cc: linux-afs@lists.infradead.org cc: netdev@vger.kernel.org --- include/trace/events/rxrpc.h | 174 +++++++++++++++++++++++-------------------- 1 file changed, 93 insertions(+), 81 deletions(-) (limited to 'include/trace') diff --git a/include/trace/events/rxrpc.h b/include/trace/events/rxrpc.h index 3b726a6c8c42..a1b126a6b0d7 100644 --- a/include/trace/events/rxrpc.h +++ b/include/trace/events/rxrpc.h @@ -119,6 +119,7 @@ EM(rxrpc_call_poke_complete, "Compl") \ EM(rxrpc_call_poke_error, "Error") \ EM(rxrpc_call_poke_idle, "Idle") \ + EM(rxrpc_call_poke_set_timeout, "Set-timo") \ EM(rxrpc_call_poke_start, "Start") \ EM(rxrpc_call_poke_timer, "Timer") \ E_(rxrpc_call_poke_timer_now, "Timer-now") @@ -340,27 +341,16 @@ E_(rxrpc_rtt_rx_requested_ack, "RACK") #define rxrpc_timer_traces \ - EM(rxrpc_timer_begin, "Begin ") \ - EM(rxrpc_timer_exp_ack, "ExpAck") \ - EM(rxrpc_timer_exp_hard, "ExpHrd") \ - EM(rxrpc_timer_exp_idle, "ExpIdl") \ - EM(rxrpc_timer_exp_keepalive, "ExpKA ") \ - EM(rxrpc_timer_exp_lost_ack, "ExpLoA") \ - EM(rxrpc_timer_exp_normal, "ExpNml") \ - EM(rxrpc_timer_exp_ping, "ExpPng") \ - EM(rxrpc_timer_exp_resend, "ExpRsn") \ - EM(rxrpc_timer_init_for_reply, "IniRpl") \ - EM(rxrpc_timer_init_for_send_reply, "SndRpl") \ - EM(rxrpc_timer_restart, "Restrt") \ - EM(rxrpc_timer_set_for_ack, "SetAck") \ - EM(rxrpc_timer_set_for_hard, "SetHrd") \ - EM(rxrpc_timer_set_for_idle, "SetIdl") \ - EM(rxrpc_timer_set_for_keepalive, "KeepAl") \ - EM(rxrpc_timer_set_for_lost_ack, "SetLoA") \ - EM(rxrpc_timer_set_for_normal, "SetNml") \ - EM(rxrpc_timer_set_for_ping, "SetPng") \ - EM(rxrpc_timer_set_for_resend, "SetRTx") \ - E_(rxrpc_timer_set_for_send, "SetSnd") + EM(rxrpc_timer_trace_delayed_ack, "DelayAck ") \ + EM(rxrpc_timer_trace_expect_rx, "ExpectRx ") \ + EM(rxrpc_timer_trace_hard, "HardLimit") \ + EM(rxrpc_timer_trace_idle, "IdleLimit") \ + EM(rxrpc_timer_trace_keepalive, "KeepAlive") \ + EM(rxrpc_timer_trace_lost_ack, "LostAck ") \ + EM(rxrpc_timer_trace_ping, "DelayPing") \ + EM(rxrpc_timer_trace_resend, "Resend ") \ + EM(rxrpc_timer_trace_resend_reset, "ResendRst") \ + E_(rxrpc_timer_trace_resend_tx, "ResendTx ") #define rxrpc_propose_ack_traces \ EM(rxrpc_propose_ack_client_tx_end, "ClTxEnd") \ @@ -1314,90 +1304,112 @@ TRACE_EVENT(rxrpc_rtt_rx, __entry->rto) ); -TRACE_EVENT(rxrpc_timer, - TP_PROTO(struct rxrpc_call *call, enum rxrpc_timer_trace why, - unsigned long now), +TRACE_EVENT(rxrpc_timer_set, + TP_PROTO(struct rxrpc_call *call, ktime_t delay, + enum rxrpc_timer_trace why), - TP_ARGS(call, why, now), + TP_ARGS(call, delay, why), TP_STRUCT__entry( __field(unsigned int, call) __field(enum rxrpc_timer_trace, why) - __field(long, now) - __field(long, ack_at) - __field(long, ack_lost_at) - __field(long, resend_at) - __field(long, ping_at) - __field(long, expect_rx_by) - __field(long, expect_req_by) - __field(long, expect_term_by) - __field(long, timer) + __field(ktime_t, delay) ), TP_fast_assign( __entry->call = call->debug_id; __entry->why = why; - __entry->now = now; - __entry->ack_at = call->delay_ack_at; - __entry->ack_lost_at = call->ack_lost_at; - __entry->resend_at = call->resend_at; - __entry->expect_rx_by = call->expect_rx_by; - __entry->expect_req_by = call->expect_req_by; - __entry->expect_term_by = call->expect_term_by; - __entry->timer = call->timer.expires; + __entry->delay = delay; ), - TP_printk("c=%08x %s a=%ld la=%ld r=%ld xr=%ld xq=%ld xt=%ld t=%ld", + TP_printk("c=%08x %s to=%lld", __entry->call, __print_symbolic(__entry->why, rxrpc_timer_traces), - __entry->ack_at - __entry->now, - __entry->ack_lost_at - __entry->now, - __entry->resend_at - __entry->now, - __entry->expect_rx_by - __entry->now, - __entry->expect_req_by - __entry->now, - __entry->expect_term_by - __entry->now, - __entry->timer - __entry->now) + ktime_to_us(__entry->delay)) + ); + +TRACE_EVENT(rxrpc_timer_exp, + TP_PROTO(struct rxrpc_call *call, ktime_t delay, + enum rxrpc_timer_trace why), + + TP_ARGS(call, delay, why), + + TP_STRUCT__entry( + __field(unsigned int, call) + __field(enum rxrpc_timer_trace, why) + __field(ktime_t, delay) + ), + + TP_fast_assign( + __entry->call = call->debug_id; + __entry->why = why; + __entry->delay = delay; + ), + + TP_printk("c=%08x %s to=%lld", + __entry->call, + __print_symbolic(__entry->why, rxrpc_timer_traces), + ktime_to_us(__entry->delay)) + ); + +TRACE_EVENT(rxrpc_timer_can, + TP_PROTO(struct rxrpc_call *call, enum rxrpc_timer_trace why), + + TP_ARGS(call, why), + + TP_STRUCT__entry( + __field(unsigned int, call) + __field(enum rxrpc_timer_trace, why) + ), + + TP_fast_assign( + __entry->call = call->debug_id; + __entry->why = why; + ), + + TP_printk("c=%08x %s", + __entry->call, + __print_symbolic(__entry->why, rxrpc_timer_traces)) + ); + +TRACE_EVENT(rxrpc_timer_restart, + TP_PROTO(struct rxrpc_call *call, ktime_t delay, unsigned long delayj), + + TP_ARGS(call, delay, delayj), + + TP_STRUCT__entry( + __field(unsigned int, call) + __field(unsigned long, delayj) + __field(ktime_t, delay) + ), + + TP_fast_assign( + __entry->call = call->debug_id; + __entry->delayj = delayj; + __entry->delay = delay; + ), + + TP_printk("c=%08x to=%lld j=%ld", + __entry->call, + ktime_to_us(__entry->delay), + __entry->delayj) ); TRACE_EVENT(rxrpc_timer_expired, - TP_PROTO(struct rxrpc_call *call, unsigned long now), + TP_PROTO(struct rxrpc_call *call), - TP_ARGS(call, now), + TP_ARGS(call), TP_STRUCT__entry( __field(unsigned int, call) - __field(long, now) - __field(long, ack_at) - __field(long, ack_lost_at) - __field(long, resend_at) - __field(long, ping_at) - __field(long, expect_rx_by) - __field(long, expect_req_by) - __field(long, expect_term_by) - __field(long, timer) ), TP_fast_assign( __entry->call = call->debug_id; - __entry->now = now; - __entry->ack_at = call->delay_ack_at; - __entry->ack_lost_at = call->ack_lost_at; - __entry->resend_at = call->resend_at; - __entry->expect_rx_by = call->expect_rx_by; - __entry->expect_req_by = call->expect_req_by; - __entry->expect_term_by = call->expect_term_by; - __entry->timer = call->timer.expires; ), - TP_printk("c=%08x EXPIRED a=%ld la=%ld r=%ld xr=%ld xq=%ld xt=%ld t=%ld", - __entry->call, - __entry->ack_at - __entry->now, - __entry->ack_lost_at - __entry->now, - __entry->resend_at - __entry->now, - __entry->expect_rx_by - __entry->now, - __entry->expect_req_by - __entry->now, - __entry->expect_term_by - __entry->now, - __entry->timer - __entry->now) + TP_printk("c=%08x EXPIRED", + __entry->call) ); TRACE_EVENT(rxrpc_rx_lose, @@ -1507,7 +1519,7 @@ TRACE_EVENT(rxrpc_drop_ack, TRACE_EVENT(rxrpc_retransmit, TP_PROTO(struct rxrpc_call *call, rxrpc_seq_t seq, - rxrpc_serial_t serial, s64 expiry), + rxrpc_serial_t serial, ktime_t expiry), TP_ARGS(call, seq, serial, expiry), @@ -1515,7 +1527,7 @@ TRACE_EVENT(rxrpc_retransmit, __field(unsigned int, call) __field(rxrpc_seq_t, seq) __field(rxrpc_serial_t, serial) - __field(s64, expiry) + __field(ktime_t, expiry) ), TP_fast_assign( @@ -1529,7 +1541,7 @@ TRACE_EVENT(rxrpc_retransmit, __entry->call, __entry->seq, __entry->serial, - __entry->expiry) + ktime_to_us(__entry->expiry)) ); TRACE_EVENT(rxrpc_congest, -- cgit