rxrpc: Trace/count transmission underflows and cwnd resets

Add a tracepoint to log when a cwnd reset occurs due to lack of
transmission on a call.

Add stat counters to count transmission underflows (ie. when we have tx
window space, but sendmsg doesn't manage to keep up), cwnd resets and
transmission failures.

Signed-off-by: David Howells <dhowells@redhat.com>
cc: Marc Dionne <marc.dionne@auristor.com>
cc: linux-afs@lists.infradead.org

diff --git a/include/trace/events/rxrpc.h b/include/trace/events/rxrpc.h
index c49b0c233594351e35975e9ab88a16c47af6eec5..b41e913ae78a5628b83985fa04ee1c20366371f3 100644 (file)
--- a/include/trace/events/rxrpc.h
+++ b/include/trace/events/rxrpc.h
@@ -1446,6 +1446,44 @@ TRACE_EVENT(rxrpc_congest,
                      __entry->sum.retrans_timeo ? " rTxTo" : "")
            );
 
+TRACE_EVENT(rxrpc_reset_cwnd,
+           TP_PROTO(struct rxrpc_call *call, ktime_t now),
+
+           TP_ARGS(call, now),
+
+           TP_STRUCT__entry(
+                   __field(unsigned int,                       call            )
+                   __field(enum rxrpc_congest_mode,            mode            )
+                   __field(unsigned short,                     cwnd            )
+                   __field(unsigned short,                     extra           )
+                   __field(rxrpc_seq_t,                        hard_ack        )
+                   __field(rxrpc_seq_t,                        prepared        )
+                   __field(ktime_t,                            since_last_tx   )
+                   __field(bool,                               has_data        )
+                            ),
+
+           TP_fast_assign(
+                   __entry->call       = call->debug_id;
+                   __entry->mode       = call->cong_mode;
+                   __entry->cwnd       = call->cong_cwnd;
+                   __entry->extra      = call->cong_extra;
+                   __entry->hard_ack   = call->acks_hard_ack;
+                   __entry->prepared   = call->tx_prepared - call->tx_bottom;
+                   __entry->since_last_tx = ktime_sub(now, call->tx_last_sent);
+                   __entry->has_data   = !list_empty(&call->tx_sendmsg);
+                          ),
+
+           TP_printk("c=%08x q=%08x %s cw=%u+%u pr=%u tm=%llu d=%u",
+                     __entry->call,
+                     __entry->hard_ack,
+                     __print_symbolic(__entry->mode, rxrpc_congest_modes),
+                     __entry->cwnd,
+                     __entry->extra,
+                     __entry->prepared,
+                     ktime_to_ns(__entry->since_last_tx),
+                     __entry->has_data)
+           );
+
 TRACE_EVENT(rxrpc_disconnect_call,
            TP_PROTO(struct rxrpc_call *call),
 

diff --git a/net/rxrpc/ar-internal.h b/net/rxrpc/ar-internal.h
index 6b993a3d4186f0b72c273a89c7e8a24776efa6fb..6cfe366ee224485130e8309bfd35bb47e60bb0e0 100644 (file)
--- a/net/rxrpc/ar-internal.h
+++ b/net/rxrpc/ar-internal.h
@@ -101,6 +101,9 @@ struct rxrpc_net {
        atomic_t                stat_tx_data_retrans;
        atomic_t                stat_tx_data_send;
        atomic_t                stat_tx_data_send_frag;
+       atomic_t                stat_tx_data_send_fail;
+       atomic_t                stat_tx_data_underflow;
+       atomic_t                stat_tx_data_cwnd_reset;
        atomic_t                stat_rx_data;
        atomic_t                stat_rx_data_reqack;
        atomic_t                stat_rx_data_jumbo;

diff --git a/net/rxrpc/call_event.c b/net/rxrpc/call_event.c
index 18591f9ecc6a70402126e01a80d6d029fe2ac0fc..9f1e490ab9761a9a6a57ce98aa5271e5242c3d0a 100644 (file)
--- a/net/rxrpc/call_event.c
+++ b/net/rxrpc/call_event.c
@@ -317,8 +317,10 @@ static void rxrpc_transmit_some_data(struct rxrpc_call *call)
        case RXRPC_CALL_CLIENT_AWAIT_REPLY:
                if (!rxrpc_tx_window_has_space(call))
                        return;
-               if (list_empty(&call->tx_sendmsg))
+               if (list_empty(&call->tx_sendmsg)) {
+                       rxrpc_inc_stat(call->rxnet, stat_tx_data_underflow);
                        return;
+               }
                rxrpc_decant_prepared_tx(call);
                break;
        default:

diff --git a/net/rxrpc/input.c b/net/rxrpc/input.c
index dd2ac5d55e1c4b66a4fee9624d44614e6dc8b307..2988e3d0c1f6f12c54f68e30e6df584fd1a34b63 100644 (file)
--- a/net/rxrpc/input.c
+++ b/net/rxrpc/input.c
@@ -27,6 +27,7 @@ static void rxrpc_congestion_management(struct rxrpc_call *call,
        enum rxrpc_congest_change change = rxrpc_cong_no_change;
        unsigned int cumulative_acks = call->cong_cumul_acks;
        unsigned int cwnd = call->cong_cwnd;
+       ktime_t now;
        bool resend = false;
 
        summary->flight_size =
@@ -59,13 +60,15 @@ static void rxrpc_congestion_management(struct rxrpc_call *call,
        /* If we haven't transmitted anything for >1RTT, we should reset the
         * congestion management state.
         */
+       now = ktime_get_real();
        if ((call->cong_mode == RXRPC_CALL_SLOW_START ||
             call->cong_mode == RXRPC_CALL_CONGEST_AVOIDANCE) &&
            ktime_before(ktime_add_us(call->tx_last_sent,
-                                     call->peer->srtt_us >> 3),
-                        ktime_get_real())
+                                     call->peer->srtt_us >> 3), now)
            ) {
+               trace_rxrpc_reset_cwnd(call, now);
                change = rxrpc_cong_idle_reset;
+               rxrpc_inc_stat(call->rxnet, stat_tx_data_cwnd_reset);
                summary->mode = RXRPC_CALL_SLOW_START;
                if (RXRPC_TX_SMSS > 2190)
                        summary->cwnd = 2;

diff --git a/net/rxrpc/output.c b/net/rxrpc/output.c
index e5d715b855fc687a5ff891ca4cc532e133c7fa4b..8147a47d170269bd2b70189712b6fadc86a65dd0 100644 (file)
--- a/net/rxrpc/output.c
+++ b/net/rxrpc/output.c
@@ -485,6 +485,7 @@ dont_set_request_ack:
 
        up_read(&conn->local->defrag_sem);
        if (ret < 0) {
+               rxrpc_inc_stat(call->rxnet, stat_tx_data_send_fail);
                rxrpc_cancel_rtt_probe(call, serial, rtt_slot);
                trace_rxrpc_tx_fail(call->debug_id, serial, ret,
                                    rxrpc_tx_point_call_data_nofrag);
@@ -567,6 +568,7 @@ send_fragmentable:
        }
 
        if (ret < 0) {
+               rxrpc_inc_stat(call->rxnet, stat_tx_data_send_fail);
                rxrpc_cancel_rtt_probe(call, serial, rtt_slot);
                trace_rxrpc_tx_fail(call->debug_id, serial, ret,
                                    rxrpc_tx_point_call_data_frag);

diff --git a/net/rxrpc/proc.c b/net/rxrpc/proc.c
index 5af7c8ee4b1adc0f862b9a48a17b449f8e3d485e..6816934cb4cf1a7494336a83ae249ac7d941278f 100644 (file)
--- a/net/rxrpc/proc.c
+++ b/net/rxrpc/proc.c
@@ -398,13 +398,16 @@ int rxrpc_stats_show(struct seq_file *seq, void *v)
        struct rxrpc_net *rxnet = rxrpc_net(seq_file_single_net(seq));
 
        seq_printf(seq,
-                  "Data     : send=%u sendf=%u\n",
+                  "Data     : send=%u sendf=%u fail=%u\n",
                   atomic_read(&rxnet->stat_tx_data_send),
-                  atomic_read(&rxnet->stat_tx_data_send_frag));
+                  atomic_read(&rxnet->stat_tx_data_send_frag),
+                  atomic_read(&rxnet->stat_tx_data_send_fail));
        seq_printf(seq,
-                  "Data-Tx  : nr=%u retrans=%u\n",
+                  "Data-Tx  : nr=%u retrans=%u uf=%u cwr=%u\n",
                   atomic_read(&rxnet->stat_tx_data),
-                  atomic_read(&rxnet->stat_tx_data_retrans));
+                  atomic_read(&rxnet->stat_tx_data_retrans),
+                  atomic_read(&rxnet->stat_tx_data_underflow),
+                  atomic_read(&rxnet->stat_tx_data_cwnd_reset));
        seq_printf(seq,
                   "Data-Rx  : nr=%u reqack=%u jumbo=%u\n",
                   atomic_read(&rxnet->stat_rx_data),
@@ -472,8 +475,11 @@ int rxrpc_stats_clear(struct file *file, char *buf, size_t size)
 
        atomic_set(&rxnet->stat_tx_data, 0);
        atomic_set(&rxnet->stat_tx_data_retrans, 0);
+       atomic_set(&rxnet->stat_tx_data_underflow, 0);
+       atomic_set(&rxnet->stat_tx_data_cwnd_reset, 0);
        atomic_set(&rxnet->stat_tx_data_send, 0);
        atomic_set(&rxnet->stat_tx_data_send_frag, 0);
+       atomic_set(&rxnet->stat_tx_data_send_fail, 0);
        atomic_set(&rxnet->stat_rx_data, 0);
        atomic_set(&rxnet->stat_rx_data_reqack, 0);
        atomic_set(&rxnet->stat_rx_data_jumbo, 0);