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 <dhowells@redhat.com>
cc: Marc Dionne <marc.dionne@auristor.com>
cc: "David S. Miller" <davem@davemloft.net>
cc: Eric Dumazet <edumazet@google.com>
cc: Jakub Kicinski <kuba@kernel.org>
cc: Paolo Abeni <pabeni@redhat.com>
cc: linux-afs@lists.infradead.org
cc: netdev@vger.kernel.org

1 files changed, 93 insertions, 81 deletions

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,