rxrpc: Add a tracepoint for the call timer

Add a tracepoint to log call timer initiation, setting and expiry.

Signed-off-by: David Howells <dhowells@redhat.com>

diff --git a/include/trace/events/rxrpc.h b/include/trace/events/rxrpc.h
index e8f2afbbe0bfaf407c8097615a59035d18720359..57322897d7450caa2826d8a5e31fd8268f3cbf2e 100644 (file)
--- a/include/trace/events/rxrpc.h
+++ b/include/trace/events/rxrpc.h
@@ -414,6 +414,42 @@ TRACE_EVENT(rxrpc_rtt_rx,
                      __entry->avg)
            );
 
+TRACE_EVENT(rxrpc_timer,
+           TP_PROTO(struct rxrpc_call *call, enum rxrpc_timer_trace why,
+                    unsigned long now),
+
+           TP_ARGS(call, why, now),
+
+           TP_STRUCT__entry(
+                   __field(struct rxrpc_call *,                call            )
+                   __field(enum rxrpc_timer_trace,             why             )
+                   __field(unsigned long,                      now             )
+                   __field(unsigned long,                      expire_at       )
+                   __field(unsigned long,                      ack_at          )
+                   __field(unsigned long,                      resend_at       )
+                   __field(unsigned long,                      timer           )
+                            ),
+
+           TP_fast_assign(
+                   __entry->call       = call;
+                   __entry->why        = why;
+                   __entry->now        = now;
+                   __entry->expire_at  = call->expire_at;
+                   __entry->ack_at     = call->ack_at;
+                   __entry->resend_at  = call->resend_at;
+                   __entry->timer      = call->timer.expires;
+                          ),
+
+           TP_printk("c=%p %s now=%lx x=%ld a=%ld r=%ld t=%ld",
+                     __entry->call,
+                     rxrpc_timer_traces[__entry->why],
+                     __entry->now,
+                     __entry->expire_at - __entry->now,
+                     __entry->ack_at - __entry->now,
+                     __entry->resend_at - __entry->now,
+                     __entry->timer - __entry->now)
+           );
+
 #endif /* _TRACE_RXRPC_H */
 
 /* This part must be outside protection */

diff --git a/net/rxrpc/ar-internal.h b/net/rxrpc/ar-internal.h
index a494d56eb236d6ae7a71109a2881862b3170c0b3..e564eca75985f6964314bf44ac1a6bbfddaad10f 100644 (file)
--- a/net/rxrpc/ar-internal.h
+++ b/net/rxrpc/ar-internal.h
@@ -678,6 +678,17 @@ enum rxrpc_rtt_rx_trace {
 
 extern const char rxrpc_rtt_rx_traces[rxrpc_rtt_rx__nr_trace][5];
 
+enum rxrpc_timer_trace {
+       rxrpc_timer_begin,
+       rxrpc_timer_expired,
+       rxrpc_timer_set_for_ack,
+       rxrpc_timer_set_for_resend,
+       rxrpc_timer_set_for_send,
+       rxrpc_timer__nr_trace
+};
+
+extern const char rxrpc_timer_traces[rxrpc_timer__nr_trace][8];
+
 extern const char *const rxrpc_pkts[];
 extern const char *rxrpc_acks(u8 reason);
 
@@ -707,7 +718,7 @@ int rxrpc_reject_call(struct rxrpc_sock *);
 /*
  * call_event.c
  */
-void rxrpc_set_timer(struct rxrpc_call *);
+void rxrpc_set_timer(struct rxrpc_call *, enum rxrpc_timer_trace);
 void rxrpc_propose_ACK(struct rxrpc_call *, u8, u16, u32, bool, bool);
 void rxrpc_process_call(struct work_struct *);
 

diff --git a/net/rxrpc/call_event.c b/net/rxrpc/call_event.c
index 8bc5c8e37ab482842dc78da7a60480dfa9f2820c..90e970ba048aae6f84ba6c44ac92fb4cd662f1ad 100644 (file)
--- a/net/rxrpc/call_event.c
+++ b/net/rxrpc/call_event.c
@@ -24,7 +24,7 @@
 /*
  * Set the timer
  */
-void rxrpc_set_timer(struct rxrpc_call *call)
+void rxrpc_set_timer(struct rxrpc_call *call, enum rxrpc_timer_trace why)
 {
        unsigned long t, now = jiffies;
 
@@ -45,6 +45,7 @@ void rxrpc_set_timer(struct rxrpc_call *call)
 
                if (call->timer.expires != t || !timer_pending(&call->timer)) {
                        mod_timer(&call->timer, t);
+                       trace_rxrpc_timer(call, why, now);
                }
        }
 
@@ -120,7 +121,7 @@ static void __rxrpc_propose_ACK(struct rxrpc_call *call, u8 ack_reason,
                _debug("deferred ACK %ld < %ld", expiry, call->ack_at - now);
                if (time_before(ack_at, call->ack_at)) {
                        call->ack_at = ack_at;
-                       rxrpc_set_timer(call);
+                       rxrpc_set_timer(call, rxrpc_timer_set_for_ack);
                }
        }
 }
@@ -293,7 +294,7 @@ recheck_state:
                goto recheck_state;
        }
 
-       rxrpc_set_timer(call);
+       rxrpc_set_timer(call, rxrpc_timer_set_for_resend);
 
        /* other events may have been raised since we started checking */
        if (call->events && call->state < RXRPC_CALL_COMPLETE) {

diff --git a/net/rxrpc/call_object.c b/net/rxrpc/call_object.c
index f2fadf667e19d3c737b28feb9f13245bbab3734b..a53f4c2c0025c6936e3ce534d42f67e1b1c7551c 100644 (file)
--- a/net/rxrpc/call_object.c
+++ b/net/rxrpc/call_object.c
@@ -76,8 +76,10 @@ static void rxrpc_call_timer_expired(unsigned long _call)
 
        _enter("%d", call->debug_id);
 
-       if (call->state < RXRPC_CALL_COMPLETE)
+       if (call->state < RXRPC_CALL_COMPLETE) {
+               trace_rxrpc_timer(call, rxrpc_timer_expired, jiffies);
                rxrpc_queue_call(call);
+       }
 }
 
 /*
@@ -200,7 +202,7 @@ static void rxrpc_start_call_timer(struct rxrpc_call *call)
        call->ack_at = expire_at;
        call->resend_at = expire_at;
        call->timer.expires = expire_at + 1;
-       rxrpc_set_timer(call);
+       rxrpc_set_timer(call, rxrpc_timer_begin);
 }
 
 /*

diff --git a/net/rxrpc/misc.c b/net/rxrpc/misc.c
index fe648711c2f7cd367d66074ecfeb6dcf50e02620..fa9942fabdf2083dcadd30e82140ead35eccb1ab 100644 (file)
--- a/net/rxrpc/misc.c
+++ b/net/rxrpc/misc.c
@@ -194,3 +194,11 @@ const char rxrpc_rtt_rx_traces[rxrpc_rtt_rx__nr_trace][5] = {
        [rxrpc_rtt_rx_ping_response]    = "PONG",
        [rxrpc_rtt_rx_requested_ack]    = "RACK",
 };
+
+const char rxrpc_timer_traces[rxrpc_timer__nr_trace][8] = {
+       [rxrpc_timer_begin]                     = "Begin ",
+       [rxrpc_timer_expired]                   = "*EXPR*",
+       [rxrpc_timer_set_for_ack]               = "SetAck",
+       [rxrpc_timer_set_for_send]              = "SetTx ",
+       [rxrpc_timer_set_for_resend]            = "SetRTx",
+};

diff --git a/net/rxrpc/sendmsg.c b/net/rxrpc/sendmsg.c
index 93e6584cd751fdec171013af1e56239a9218ddce..99939372b5a4c37d47d66a6b6d348b0a7ff7cab0 100644 (file)
--- a/net/rxrpc/sendmsg.c
+++ b/net/rxrpc/sendmsg.c
@@ -153,7 +153,7 @@ static void rxrpc_queue_packet(struct rxrpc_call *call, struct sk_buff *skb,
 
                if (time_before(resend_at, call->resend_at)) {
                        call->resend_at = resend_at;
-                       rxrpc_set_timer(call);
+                       rxrpc_set_timer(call, rxrpc_timer_set_for_send);
                }
        }