rxrpc: Trace packet transmission

Trace successful packet transmission (kernel_sendmsg() succeeded, that is)
in AF_RXRPC.  We can share the enum that defines the transmission points
with the trace_rxrpc_tx_fail() tracepoint, so rename its constants to be
applicable to both.

Also, save the internal call->debug_id in the rxrpc_channel struct so that
it can be used in retransmission trace lines.

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

diff --git a/include/trace/events/rxrpc.h b/include/trace/events/rxrpc.h
index 4fff00e9da8ac43b581fa95a318a59db43832611..2aa6f615b60d100b7719e9dad8748b7e42c1c811 100644 (file)
--- a/include/trace/events/rxrpc.h
+++ b/include/trace/events/rxrpc.h
@@ -211,18 +211,18 @@ enum rxrpc_congest_change {
        rxrpc_cong_saw_nack,
 };
 
-enum rxrpc_tx_fail_trace {
-       rxrpc_tx_fail_call_abort,
-       rxrpc_tx_fail_call_ack,
-       rxrpc_tx_fail_call_data_frag,
-       rxrpc_tx_fail_call_data_nofrag,
-       rxrpc_tx_fail_call_final_resend,
-       rxrpc_tx_fail_conn_abort,
-       rxrpc_tx_fail_conn_challenge,
-       rxrpc_tx_fail_conn_response,
-       rxrpc_tx_fail_reject,
-       rxrpc_tx_fail_version_keepalive,
-       rxrpc_tx_fail_version_reply,
+enum rxrpc_tx_point {
+       rxrpc_tx_point_call_abort,
+       rxrpc_tx_point_call_ack,
+       rxrpc_tx_point_call_data_frag,
+       rxrpc_tx_point_call_data_nofrag,
+       rxrpc_tx_point_call_final_resend,
+       rxrpc_tx_point_conn_abort,
+       rxrpc_tx_point_rxkad_challenge,
+       rxrpc_tx_point_rxkad_response,
+       rxrpc_tx_point_reject,
+       rxrpc_tx_point_version_keepalive,
+       rxrpc_tx_point_version_reply,
 };
 
 #endif /* end __RXRPC_DECLARE_TRACE_ENUMS_ONCE_ONLY */
@@ -452,18 +452,18 @@ enum rxrpc_tx_fail_trace {
        EM(RXRPC_CALL_LOCAL_ERROR,              "LocalError") \
        E_(RXRPC_CALL_NETWORK_ERROR,            "NetError")
 
-#define rxrpc_tx_fail_traces \
-       EM(rxrpc_tx_fail_call_abort,            "CallAbort") \
-       EM(rxrpc_tx_fail_call_ack,              "CallAck") \
-       EM(rxrpc_tx_fail_call_data_frag,        "CallDataFrag") \
-       EM(rxrpc_tx_fail_call_data_nofrag,      "CallDataNofrag") \
-       EM(rxrpc_tx_fail_call_final_resend,     "CallFinalResend") \
-       EM(rxrpc_tx_fail_conn_abort,            "ConnAbort") \
-       EM(rxrpc_tx_fail_conn_challenge,        "ConnChall") \
-       EM(rxrpc_tx_fail_conn_response,         "ConnResp") \
-       EM(rxrpc_tx_fail_reject,                "Reject") \
-       EM(rxrpc_tx_fail_version_keepalive,     "VerKeepalive") \
-       E_(rxrpc_tx_fail_version_reply,         "VerReply")
+#define rxrpc_tx_points \
+       EM(rxrpc_tx_point_call_abort,           "CallAbort") \
+       EM(rxrpc_tx_point_call_ack,             "CallAck") \
+       EM(rxrpc_tx_point_call_data_frag,       "CallDataFrag") \
+       EM(rxrpc_tx_point_call_data_nofrag,     "CallDataNofrag") \
+       EM(rxrpc_tx_point_call_final_resend,    "CallFinalResend") \
+       EM(rxrpc_tx_point_conn_abort,           "ConnAbort") \
+       EM(rxrpc_tx_point_reject,               "Reject") \
+       EM(rxrpc_tx_point_rxkad_challenge,      "RxkadChall") \
+       EM(rxrpc_tx_point_rxkad_response,       "RxkadResp") \
+       EM(rxrpc_tx_point_version_keepalive,    "VerKeepalive") \
+       E_(rxrpc_tx_point_version_reply,        "VerReply")
 
 /*
  * Export enum symbols via userspace.
@@ -488,7 +488,7 @@ rxrpc_propose_ack_traces;
 rxrpc_propose_ack_outcomes;
 rxrpc_congest_modes;
 rxrpc_congest_changes;
-rxrpc_tx_fail_traces;
+rxrpc_tx_points;
 
 /*
  * Now redefine the EM() and E_() macros to map the enums to the strings that
@@ -801,7 +801,7 @@ TRACE_EVENT(rxrpc_transmit,
            );
 
 TRACE_EVENT(rxrpc_rx_data,
-           TP_PROTO(struct rxrpc_call *call, rxrpc_seq_t seq,
+           TP_PROTO(unsigned int call, rxrpc_seq_t seq,
                     rxrpc_serial_t serial, u8 flags, u8 anno),
 
            TP_ARGS(call, seq, serial, flags, anno),
@@ -815,7 +815,7 @@ TRACE_EVENT(rxrpc_rx_data,
                             ),
 
            TP_fast_assign(
-                   __entry->call = call->debug_id;
+                   __entry->call = call;
                    __entry->seq = seq;
                    __entry->serial = serial;
                    __entry->flags = flags;
@@ -918,6 +918,37 @@ TRACE_EVENT(rxrpc_rx_rwind_change,
                      __entry->wake ? " wake" : "")
            );
 
+TRACE_EVENT(rxrpc_tx_packet,
+           TP_PROTO(unsigned int call_id, struct rxrpc_wire_header *whdr,
+                    enum rxrpc_tx_point where),
+
+           TP_ARGS(call_id, whdr, where),
+
+           TP_STRUCT__entry(
+                   __field(unsigned int,                       call    )
+                   __field(enum rxrpc_tx_point,                where   )
+                   __field_struct(struct rxrpc_wire_header,    whdr    )
+                            ),
+
+           TP_fast_assign(
+                   __entry->call = call_id;
+                   memcpy(&__entry->whdr, whdr, sizeof(__entry->whdr));
+                          ),
+
+           TP_printk("c=%08x %08x:%08x:%08x:%04x %08x %08x %02x %02x %s %s",
+                     __entry->call,
+                     ntohl(__entry->whdr.epoch),
+                     ntohl(__entry->whdr.cid),
+                     ntohl(__entry->whdr.callNumber),
+                     ntohs(__entry->whdr.serviceId),
+                     ntohl(__entry->whdr.serial),
+                     ntohl(__entry->whdr.seq),
+                     __entry->whdr.type, __entry->whdr.flags,
+                     __entry->whdr.type <= 15 ?
+                     __print_symbolic(__entry->whdr.type, rxrpc_pkts) : "?UNK",
+                     __print_symbolic(__entry->where, rxrpc_tx_points))
+           );
+
 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),
@@ -928,6 +959,8 @@ TRACE_EVENT(rxrpc_tx_data,
                    __field(unsigned int,               call            )
                    __field(rxrpc_seq_t,                seq             )
                    __field(rxrpc_serial_t,             serial          )
+                   __field(u32,                        cid             )
+                   __field(u32,                        call_id         )
                    __field(u8,                         flags           )
                    __field(bool,                       retrans         )
                    __field(bool,                       lose            )
@@ -935,6 +968,8 @@ TRACE_EVENT(rxrpc_tx_data,
 
            TP_fast_assign(
                    __entry->call = call->debug_id;
+                   __entry->cid = call->cid;
+                   __entry->call_id = call->call_id;
                    __entry->seq = seq;
                    __entry->serial = serial;
                    __entry->flags = flags;
@@ -942,8 +977,10 @@ TRACE_EVENT(rxrpc_tx_data,
                    __entry->lose = lose;
                           ),
 
-           TP_printk("c=%08x DATA %08x q=%08x fl=%02x%s%s",
+           TP_printk("c=%08x DATA %08x:%08x %08x q=%08x fl=%02x%s%s",
                      __entry->call,
+                     __entry->cid,
+                     __entry->call_id,
                      __entry->serial,
                      __entry->seq,
                      __entry->flags,
@@ -952,7 +989,7 @@ TRACE_EVENT(rxrpc_tx_data,
            );
 
 TRACE_EVENT(rxrpc_tx_ack,
-           TP_PROTO(struct rxrpc_call *call, rxrpc_serial_t serial,
+           TP_PROTO(unsigned int call, rxrpc_serial_t serial,
                     rxrpc_seq_t ack_first, rxrpc_serial_t ack_serial,
                     u8 reason, u8 n_acks),
 
@@ -968,7 +1005,7 @@ TRACE_EVENT(rxrpc_tx_ack,
                             ),
 
            TP_fast_assign(
-                   __entry->call = call ? call->debug_id : 0;
+                   __entry->call = call;
                    __entry->serial = serial;
                    __entry->ack_first = ack_first;
                    __entry->ack_serial = ack_serial;
@@ -1434,29 +1471,29 @@ TRACE_EVENT(rxrpc_rx_icmp,
 
 TRACE_EVENT(rxrpc_tx_fail,
            TP_PROTO(unsigned int debug_id, rxrpc_serial_t serial, int ret,
-                    enum rxrpc_tx_fail_trace what),
+                    enum rxrpc_tx_point where),
 
-           TP_ARGS(debug_id, serial, ret, what),
+           TP_ARGS(debug_id, serial, ret, where),
 
            TP_STRUCT__entry(
                    __field(unsigned int,               debug_id        )
                    __field(rxrpc_serial_t,             serial          )
                    __field(int,                        ret             )
-                   __field(enum rxrpc_tx_fail_trace,   what            )
+                   __field(enum rxrpc_tx_point,        where           )
                             ),
 
            TP_fast_assign(
                    __entry->debug_id = debug_id;
                    __entry->serial = serial;
                    __entry->ret = ret;
-                   __entry->what = what;
+                   __entry->where = where;
                           ),
 
            TP_printk("c=%08x r=%x ret=%d %s",
                      __entry->debug_id,
                      __entry->serial,
                      __entry->ret,
-                     __print_symbolic(__entry->what, rxrpc_tx_fail_traces))
+                     __print_symbolic(__entry->where, rxrpc_tx_points))
            );
 
 TRACE_EVENT(rxrpc_call_reset,

diff --git a/net/rxrpc/ar-internal.h b/net/rxrpc/ar-internal.h
index 5fb7d3254d9e290106dda6566ed393eb6a2c3696..7eee955a768a9a5049b540aab65e020b6710afb8 100644 (file)
--- a/net/rxrpc/ar-internal.h
+++ b/net/rxrpc/ar-internal.h
@@ -420,6 +420,7 @@ struct rxrpc_connection {
        struct rxrpc_channel {
                unsigned long           final_ack_at;   /* Time at which to issue final ACK */
                struct rxrpc_call __rcu *call;          /* Active call */
+               unsigned int            call_debug_id;  /* call->debug_id */
                u32                     call_id;        /* ID of current call */
                u32                     call_counter;   /* Call ID counter */
                u32                     last_call;      /* ID of last call */

diff --git a/net/rxrpc/conn_client.c b/net/rxrpc/conn_client.c
index e4bfbd7e48a81bbf666e5eb55cd651d73274f662..f8f37188a9322829b8f4277c09b7329d2f4c1da0 100644 (file)
--- a/net/rxrpc/conn_client.c
+++ b/net/rxrpc/conn_client.c
@@ -590,6 +590,7 @@ static void rxrpc_activate_one_channel(struct rxrpc_connection *conn,
         */
        smp_wmb();
        chan->call_id   = call_id;
+       chan->call_debug_id = call->debug_id;
        rcu_assign_pointer(chan->call, call);
        wake_up(&call->waitq);
 }

diff --git a/net/rxrpc/conn_event.c b/net/rxrpc/conn_event.c
index d46a68807f083265ba2dc5fbee488353951a818f..84d40ba9856f462504fe6675391dcea7fd2bd642 100644 (file)
--- a/net/rxrpc/conn_event.c
+++ b/net/rxrpc/conn_event.c
@@ -129,7 +129,7 @@ static void rxrpc_conn_retransmit_call(struct rxrpc_connection *conn,
                _proto("Tx ABORT %%%u { %d } [re]", serial, conn->local_abort);
                break;
        case RXRPC_PACKET_TYPE_ACK:
-               trace_rxrpc_tx_ack(NULL, serial,
+               trace_rxrpc_tx_ack(chan->call_debug_id, serial,
                                   ntohl(pkt.ack.firstPacket),
                                   ntohl(pkt.ack.serial),
                                   pkt.ack.reason, 0);
@@ -140,8 +140,11 @@ static void rxrpc_conn_retransmit_call(struct rxrpc_connection *conn,
        ret = kernel_sendmsg(conn->params.local->socket, &msg, iov, ioc, len);
        conn->params.peer->last_tx_at = ktime_get_real();
        if (ret < 0)
-               trace_rxrpc_tx_fail(conn->debug_id, serial, ret,
-                                   rxrpc_tx_fail_call_final_resend);
+               trace_rxrpc_tx_fail(chan->call_debug_id, serial, ret,
+                                   rxrpc_tx_point_call_final_resend);
+       else
+               trace_rxrpc_tx_packet(chan->call_debug_id, &pkt.whdr,
+                                     rxrpc_tx_point_call_final_resend);
 
        _leave("");
 }
@@ -242,11 +245,13 @@ static int rxrpc_abort_connection(struct rxrpc_connection *conn,
        ret = kernel_sendmsg(conn->params.local->socket, &msg, iov, 2, len);
        if (ret < 0) {
                trace_rxrpc_tx_fail(conn->debug_id, serial, ret,
-                                   rxrpc_tx_fail_conn_abort);
+                                   rxrpc_tx_point_conn_abort);
                _debug("sendmsg failed: %d", ret);
                return -EAGAIN;
        }
 
+       trace_rxrpc_tx_packet(conn->debug_id, &whdr, rxrpc_tx_point_conn_abort);
+
        conn->params.peer->last_tx_at = ktime_get_real();
 
        _leave(" = 0");

diff --git a/net/rxrpc/input.c b/net/rxrpc/input.c
index 608d078a4981fd78d42b1e3c87b983a7ec0be0db..8989d760b6b2ba554c0bf3ebaac49b2053413e66 100644 (file)
--- a/net/rxrpc/input.c
+++ b/net/rxrpc/input.c
@@ -496,7 +496,7 @@ static void rxrpc_input_data(struct rxrpc_call *call, struct sk_buff *skb,
                        return rxrpc_proto_abort("LSA", call, seq);
        }
 
-       trace_rxrpc_rx_data(call, seq, serial, flags, annotation);
+       trace_rxrpc_rx_data(call->debug_id, seq, serial, flags, annotation);
        if (before_eq(seq, hard_ack)) {
                ack = RXRPC_ACK_DUPLICATE;
                ack_serial = serial;
@@ -592,6 +592,10 @@ static void rxrpc_input_data(struct rxrpc_call *call, struct sk_buff *skb,
                rxrpc_propose_ACK(call, ack, skew, ack_serial,
                                  immediate_ack, true,
                                  rxrpc_propose_ack_input_data);
+       else
+               rxrpc_propose_ACK(call, RXRPC_ACK_DELAY, skew, serial,
+                                 false, true,
+                                 rxrpc_propose_ack_input_data);
 
        if (sp->hdr.seq == READ_ONCE(call->rx_hard_ack) + 1)
                rxrpc_notify_socket(call);
@@ -1262,6 +1266,11 @@ void rxrpc_data_ready(struct sock *udp_sk)
                        /* But otherwise we need to retransmit the final packet
                         * from data cached in the connection record.
                         */
+                       if (sp->hdr.type == RXRPC_PACKET_TYPE_DATA)
+                               trace_rxrpc_rx_data(chan->call_debug_id,
+                                                   sp->hdr.seq,
+                                                   sp->hdr.serial,
+                                                   sp->hdr.flags, 0);
                        rxrpc_post_packet_to_conn(conn, skb);
                        goto out_unlock;
                }

diff --git a/net/rxrpc/local_event.c b/net/rxrpc/local_event.c
index 8325f1b868404690d54a6e98d70b6896c3537f72..13bd8a4dfac7126effa56e4a5766634e8278e0cc 100644 (file)
--- a/net/rxrpc/local_event.c
+++ b/net/rxrpc/local_event.c
@@ -72,7 +72,10 @@ static void rxrpc_send_version_request(struct rxrpc_local *local,
        ret = kernel_sendmsg(local->socket, &msg, iov, 2, len);
        if (ret < 0)
                trace_rxrpc_tx_fail(local->debug_id, 0, ret,
-                                   rxrpc_tx_fail_version_reply);
+                                   rxrpc_tx_point_version_reply);
+       else
+               trace_rxrpc_tx_packet(local->debug_id, &whdr,
+                                     rxrpc_tx_point_version_reply);
 
        _leave("");
 }

diff --git a/net/rxrpc/output.c b/net/rxrpc/output.c
index f03de1c59ba37678f36f3a5c0778f3f3f9274757..801dbf3d34789268f78f607574913f08bffc99cc 100644 (file)
--- a/net/rxrpc/output.c
+++ b/net/rxrpc/output.c
@@ -183,7 +183,7 @@ int rxrpc_send_ack_packet(struct rxrpc_call *call, bool ping,
 
        serial = atomic_inc_return(&conn->serial);
        pkt->whdr.serial = htonl(serial);
-       trace_rxrpc_tx_ack(call, serial,
+       trace_rxrpc_tx_ack(call->debug_id, serial,
                           ntohl(pkt->ack.firstPacket),
                           ntohl(pkt->ack.serial),
                           pkt->ack.reason, pkt->ack.nAcks);
@@ -212,7 +212,10 @@ int rxrpc_send_ack_packet(struct rxrpc_call *call, bool ping,
        conn->params.peer->last_tx_at = ktime_get_real();
        if (ret < 0)
                trace_rxrpc_tx_fail(call->debug_id, serial, ret,
-                                   rxrpc_tx_fail_call_ack);
+                                   rxrpc_tx_point_call_ack);
+       else
+               trace_rxrpc_tx_packet(call->debug_id, &pkt->whdr,
+                                     rxrpc_tx_point_call_ack);
 
        if (call->state < RXRPC_CALL_COMPLETE) {
                if (ret < 0) {
@@ -299,7 +302,10 @@ int rxrpc_send_abort_packet(struct rxrpc_call *call)
        conn->params.peer->last_tx_at = ktime_get_real();
        if (ret < 0)
                trace_rxrpc_tx_fail(call->debug_id, serial, ret,
-                                   rxrpc_tx_fail_call_abort);
+                                   rxrpc_tx_point_call_abort);
+       else
+               trace_rxrpc_tx_packet(call->debug_id, &pkt.whdr,
+                                     rxrpc_tx_point_call_abort);
 
 
        rxrpc_put_connection(conn);
@@ -396,7 +402,10 @@ int rxrpc_send_data_packet(struct rxrpc_call *call, struct sk_buff *skb,
        up_read(&conn->params.local->defrag_sem);
        if (ret < 0)
                trace_rxrpc_tx_fail(call->debug_id, serial, ret,
-                                   rxrpc_tx_fail_call_data_nofrag);
+                                   rxrpc_tx_point_call_data_nofrag);
+       else
+               trace_rxrpc_tx_packet(call->debug_id, &whdr,
+                                     rxrpc_tx_point_call_data_nofrag);
        if (ret == -EMSGSIZE)
                goto send_fragmentable;
 
@@ -488,7 +497,10 @@ int rxrpc_send_data_packet(struct rxrpc_call *call, struct sk_buff *skb,
 
        if (ret < 0)
                trace_rxrpc_tx_fail(call->debug_id, serial, ret,
-                                   rxrpc_tx_fail_call_data_frag);
+                                   rxrpc_tx_point_call_data_frag);
+       else
+               trace_rxrpc_tx_packet(call->debug_id, &whdr,
+                                     rxrpc_tx_point_call_data_frag);
 
        up_write(&conn->params.local->defrag_sem);
        goto done;
@@ -545,7 +557,10 @@ void rxrpc_reject_packets(struct rxrpc_local *local)
                        ret = kernel_sendmsg(local->socket, &msg, iov, 2, size);
                        if (ret < 0)
                                trace_rxrpc_tx_fail(local->debug_id, 0, ret,
-                                                   rxrpc_tx_fail_reject);
+                                                   rxrpc_tx_point_reject);
+                       else
+                               trace_rxrpc_tx_packet(local->debug_id, &whdr,
+                                                     rxrpc_tx_point_reject);
                }
 
                rxrpc_free_skb(skb, rxrpc_skb_rx_freed);
@@ -597,7 +612,10 @@ void rxrpc_send_keepalive(struct rxrpc_peer *peer)
        ret = kernel_sendmsg(peer->local->socket, &msg, iov, 2, len);
        if (ret < 0)
                trace_rxrpc_tx_fail(peer->debug_id, 0, ret,
-                                   rxrpc_tx_fail_version_keepalive);
+                                   rxrpc_tx_point_version_keepalive);
+       else
+               trace_rxrpc_tx_packet(peer->debug_id, &whdr,
+                                     rxrpc_tx_point_version_keepalive);
 
        peer->last_tx_at = ktime_get_real();
        _leave("");

diff --git a/net/rxrpc/rxkad.c b/net/rxrpc/rxkad.c
index 278ac0807a60a8664bbb825ccd06737a595d8631..6988073ae84238921b0d10e6a7a7944ea2e6537e 100644 (file)
--- a/net/rxrpc/rxkad.c
+++ b/net/rxrpc/rxkad.c
@@ -665,11 +665,13 @@ static int rxkad_issue_challenge(struct rxrpc_connection *conn)
        ret = kernel_sendmsg(conn->params.local->socket, &msg, iov, 2, len);
        if (ret < 0) {
                trace_rxrpc_tx_fail(conn->debug_id, serial, ret,
-                                   rxrpc_tx_fail_conn_challenge);
+                                   rxrpc_tx_point_rxkad_challenge);
                return -EAGAIN;
        }
 
        conn->params.peer->last_tx_at = ktime_get_real();
+       trace_rxrpc_tx_packet(conn->debug_id, &whdr,
+                             rxrpc_tx_point_rxkad_challenge);
        _leave(" = 0");
        return 0;
 }
@@ -721,11 +723,12 @@ static int rxkad_send_response(struct rxrpc_connection *conn,
        ret = kernel_sendmsg(conn->params.local->socket, &msg, iov, 3, len);
        if (ret < 0) {
                trace_rxrpc_tx_fail(conn->debug_id, serial, ret,
-                                   rxrpc_tx_fail_conn_response);
+                                   rxrpc_tx_point_rxkad_response);
                return -EAGAIN;
        }
 
        conn->params.peer->last_tx_at = ktime_get_real();
+       trace_rxrpc_tx_packet(0, &whdr, rxrpc_tx_point_rxkad_response);
        _leave(" = 0");
        return 0;
 }