summaryrefslogtreecommitdiff
diff options
context:
space:
mode:
authorDavid Howells <dhowells@redhat.com>2022-11-11 16:47:35 +0300
committerDavid Howells <dhowells@redhat.com>2022-12-01 16:36:42 +0300
commit32cf8edb079a6a687a2b5dba39a813a0bbd0ddf9 (patch)
treeacbf8a435043daa16df69c2d9f2fd3ea769cc788
parent3dd9c8b5f09fd24652729a3da5c5efa3ec2c4590 (diff)
downloadlinux-32cf8edb079a6a687a2b5dba39a813a0bbd0ddf9.tar.xz
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
-rw-r--r--include/trace/events/rxrpc.h38
-rw-r--r--net/rxrpc/ar-internal.h3
-rw-r--r--net/rxrpc/call_event.c4
-rw-r--r--net/rxrpc/input.c7
-rw-r--r--net/rxrpc/output.c2
-rw-r--r--net/rxrpc/proc.c14
6 files changed, 61 insertions, 7 deletions
diff --git a/include/trace/events/rxrpc.h b/include/trace/events/rxrpc.h
index c49b0c233594..b41e913ae78a 100644
--- 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 6b993a3d4186..6cfe366ee224 100644
--- 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 18591f9ecc6a..9f1e490ab976 100644
--- 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 dd2ac5d55e1c..2988e3d0c1f6 100644
--- 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 e5d715b855fc..8147a47d1702 100644
--- 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 5af7c8ee4b1a..6816934cb4cf 100644
--- 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);