From f597a5792ada511e3c69ecf7201fc178c574d822 Mon Sep 17 00:00:00 2001 From: YueHaibing Date: Wed, 1 Aug 2018 17:52:34 +0800 Subject: [PATCH 01/10] rxrpc: remove redundant variables 'sp' and 'did_discard' Variables 'sp' and 'did_discard' are being assigned, but are never used, hence they are redundant and can be removed. fix following warning: net/rxrpc/call_event.c:165:25: warning: variable 'sp' set but not used [-Wunused-but-set-variable] net/rxrpc/conn_client.c:1054:7: warning: variable 'did_discard' set but not used [-Wunused-but-set-variable] Signed-off-by: YueHaibing Signed-off-by: David Howells --- net/rxrpc/call_event.c | 2 -- net/rxrpc/conn_client.c | 2 -- 2 files changed, 4 deletions(-) diff --git a/net/rxrpc/call_event.c b/net/rxrpc/call_event.c index 20210418904b..8e7434e92097 100644 --- a/net/rxrpc/call_event.c +++ b/net/rxrpc/call_event.c @@ -162,7 +162,6 @@ static void rxrpc_congestion_timeout(struct rxrpc_call *call) */ static void rxrpc_resend(struct rxrpc_call *call, unsigned long now_j) { - struct rxrpc_skb_priv *sp; struct sk_buff *skb; unsigned long resend_at; rxrpc_seq_t cursor, seq, top; @@ -207,7 +206,6 @@ static void rxrpc_resend(struct rxrpc_call *call, unsigned long now_j) skb = call->rxtx_buffer[ix]; rxrpc_see_skb(skb, rxrpc_skb_tx_seen); - sp = rxrpc_skb(skb); if (anno_type == RXRPC_TX_ANNO_UNACK) { if (ktime_after(skb->tstamp, max_age)) { diff --git a/net/rxrpc/conn_client.c b/net/rxrpc/conn_client.c index 5736f643c516..e4bfbd7e48a8 100644 --- a/net/rxrpc/conn_client.c +++ b/net/rxrpc/conn_client.c @@ -1051,7 +1051,6 @@ void rxrpc_discard_expired_client_conns(struct work_struct *work) container_of(work, struct rxrpc_net, client_conn_reaper); unsigned long expiry, conn_expires_at, now; unsigned int nr_conns; - bool did_discard = false; _enter(""); @@ -1113,7 +1112,6 @@ void rxrpc_discard_expired_client_conns(struct work_struct *work) * If someone re-sets the flag and re-gets the ref, that's fine. */ rxrpc_put_connection(conn); - did_discard = true; nr_conns--; goto next; From 887763bbc34112f4126ec52d16072ba736c83a6f Mon Sep 17 00:00:00 2001 From: David Howells Date: Mon, 23 Jul 2018 17:18:36 +0100 Subject: [PATCH 02/10] rxrpc: Display call expect-receive-by timeout in proc Display in /proc/net/rxrpc/calls the timeout by which a call next expects to receive a packet. This makes it easier to debug timeout issues. Signed-off-by: David Howells --- net/rxrpc/proc.c | 14 +++++++++++--- 1 file changed, 11 insertions(+), 3 deletions(-) diff --git a/net/rxrpc/proc.c b/net/rxrpc/proc.c index d9fca8c4bcdc..bc6f27c8869d 100644 --- a/net/rxrpc/proc.c +++ b/net/rxrpc/proc.c @@ -63,6 +63,7 @@ static int rxrpc_call_seq_show(struct seq_file *seq, void *v) struct rxrpc_peer *peer; struct rxrpc_call *call; struct rxrpc_net *rxnet = rxrpc_net(seq_file_net(seq)); + unsigned long timeout = 0, nowj; rxrpc_seq_t tx_hard_ack, rx_hard_ack; char lbuff[50], rbuff[50]; @@ -71,7 +72,7 @@ static int rxrpc_call_seq_show(struct seq_file *seq, void *v) "Proto Local " " Remote " " SvID ConnID CallID End Use State Abort " - " UserID\n"); + " UserID TxSeq TW RxSeq RW RxTimo\n"); return 0; } @@ -94,11 +95,17 @@ static int rxrpc_call_seq_show(struct seq_file *seq, void *v) else strcpy(rbuff, "no_connection"); + if (call->state != RXRPC_CALL_SERVER_PREALLOC) { + timeout = READ_ONCE(call->expect_rx_by); + nowj = jiffies; + timeout -= jiffies; + } + tx_hard_ack = READ_ONCE(call->tx_hard_ack); rx_hard_ack = READ_ONCE(call->rx_hard_ack); seq_printf(seq, "UDP %-47.47s %-47.47s %4x %08x %08x %s %3u" - " %-8.8s %08x %lx %08x %02x %08x %02x\n", + " %-8.8s %08x %lx %08x %02x %08x %02x %06lx\n", lbuff, rbuff, call->service_id, @@ -110,7 +117,8 @@ static int rxrpc_call_seq_show(struct seq_file *seq, void *v) call->abort_code, call->user_call_ID, tx_hard_ack, READ_ONCE(call->tx_top) - tx_hard_ack, - rx_hard_ack, READ_ONCE(call->rx_top) - rx_hard_ack); + rx_hard_ack, READ_ONCE(call->rx_top) - rx_hard_ack, + timeout); return 0; } From 6b97bd7a272cddc48adb384142db99a935834765 Mon Sep 17 00:00:00 2001 From: David Howells Date: Mon, 23 Jul 2018 17:18:36 +0100 Subject: [PATCH 03/10] rxrpc: Show some more information through /proc files Show the four current call IDs in /proc/net/rxrpc/conns. Show the current packet Rx serial number in /proc/net/rxrpc/calls. Signed-off-by: David Howells --- net/rxrpc/proc.c | 13 +++++++++---- 1 file changed, 9 insertions(+), 4 deletions(-) diff --git a/net/rxrpc/proc.c b/net/rxrpc/proc.c index bc6f27c8869d..163d05df339d 100644 --- a/net/rxrpc/proc.c +++ b/net/rxrpc/proc.c @@ -72,7 +72,7 @@ static int rxrpc_call_seq_show(struct seq_file *seq, void *v) "Proto Local " " Remote " " SvID ConnID CallID End Use State Abort " - " UserID TxSeq TW RxSeq RW RxTimo\n"); + " UserID TxSeq TW RxSeq RW RxSerial RxTimo\n"); return 0; } @@ -105,7 +105,7 @@ static int rxrpc_call_seq_show(struct seq_file *seq, void *v) rx_hard_ack = READ_ONCE(call->rx_hard_ack); seq_printf(seq, "UDP %-47.47s %-47.47s %4x %08x %08x %s %3u" - " %-8.8s %08x %lx %08x %02x %08x %02x %06lx\n", + " %-8.8s %08x %lx %08x %02x %08x %02x %08x %06lx\n", lbuff, rbuff, call->service_id, @@ -118,6 +118,7 @@ static int rxrpc_call_seq_show(struct seq_file *seq, void *v) call->user_call_ID, tx_hard_ack, READ_ONCE(call->tx_top) - tx_hard_ack, rx_hard_ack, READ_ONCE(call->rx_top) - rx_hard_ack, + call->rx_serial, timeout); return 0; @@ -187,7 +188,7 @@ static int rxrpc_connection_seq_show(struct seq_file *seq, void *v) print: seq_printf(seq, "UDP %-47.47s %-47.47s %4x %08x %s %3u" - " %s %08x %08x %08x\n", + " %s %08x %08x %08x %08x %08x %08x %08x\n", lbuff, rbuff, conn->service_id, @@ -197,7 +198,11 @@ static int rxrpc_connection_seq_show(struct seq_file *seq, void *v) rxrpc_conn_states[conn->state], key_serial(conn->params.key), atomic_read(&conn->serial), - conn->hi_serial); + conn->hi_serial, + conn->channels[0].call_id, + conn->channels[1].call_id, + conn->channels[2].call_id, + conn->channels[3].call_id); return 0; } From f3f8337c9e2a4964671c652469202ec485afddc0 Mon Sep 17 00:00:00 2001 From: David Howells Date: Mon, 23 Jul 2018 17:18:36 +0100 Subject: [PATCH 04/10] rxrpc: Fix the trace for terminal ACK (re)transmission Fix the trace for terminal ACK (re)transmission to put in the right parameters. Signed-off-by: David Howells --- net/rxrpc/conn_event.c | 6 ++++-- 1 file changed, 4 insertions(+), 2 deletions(-) diff --git a/net/rxrpc/conn_event.c b/net/rxrpc/conn_event.c index 8229a52c2acd..d46a68807f08 100644 --- a/net/rxrpc/conn_event.c +++ b/net/rxrpc/conn_event.c @@ -129,8 +129,10 @@ 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, chan->last_seq, 0, - RXRPC_ACK_DUPLICATE, 0); + trace_rxrpc_tx_ack(NULL, serial, + ntohl(pkt.ack.firstPacket), + ntohl(pkt.ack.serial), + pkt.ack.reason, 0); _proto("Tx ACK %%%u [re]", serial); break; } From 4764c0da69dc500791c840c88dfd940d13b452e7 Mon Sep 17 00:00:00 2001 From: David Howells Date: Mon, 23 Jul 2018 17:18:37 +0100 Subject: [PATCH 05/10] 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 --- include/trace/events/rxrpc.h | 107 +++++++++++++++++++++++------------ net/rxrpc/ar-internal.h | 1 + net/rxrpc/conn_client.c | 1 + net/rxrpc/conn_event.c | 13 +++-- net/rxrpc/input.c | 11 +++- net/rxrpc/local_event.c | 5 +- net/rxrpc/output.c | 32 ++++++++--- net/rxrpc/rxkad.c | 7 ++- 8 files changed, 127 insertions(+), 50 deletions(-) diff --git a/include/trace/events/rxrpc.h b/include/trace/events/rxrpc.h index 4fff00e9da8a..2aa6f615b60d 100644 --- 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 5fb7d3254d9e..7eee955a768a 100644 --- 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 e4bfbd7e48a8..f8f37188a932 100644 --- 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 d46a68807f08..84d40ba9856f 100644 --- 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 608d078a4981..8989d760b6b2 100644 --- 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 8325f1b86840..13bd8a4dfac7 100644 --- 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 f03de1c59ba3..801dbf3d3478 100644 --- 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 278ac0807a60..6988073ae842 100644 --- 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; } From 197445aff13c164794efb6d87a28762e843622d8 Mon Sep 17 00:00:00 2001 From: David Howells Date: Mon, 23 Jul 2018 17:18:37 +0100 Subject: [PATCH 06/10] rxrpc: Fix ACK proposal tracepoint Fix the ACK proposal tracepoint outcomes list by making the one that's an empty string not an empty string - which gets rendered as a hex number string instead. Signed-off-by: David Howells --- include/trace/events/rxrpc.h | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/include/trace/events/rxrpc.h b/include/trace/events/rxrpc.h index 2aa6f615b60d..c1a800a6dee3 100644 --- a/include/trace/events/rxrpc.h +++ b/include/trace/events/rxrpc.h @@ -396,7 +396,7 @@ enum rxrpc_tx_point { #define rxrpc_propose_ack_outcomes \ EM(rxrpc_propose_ack_subsume, " Subsume") \ EM(rxrpc_propose_ack_update, " Update") \ - E_(rxrpc_propose_ack_use, "") + E_(rxrpc_propose_ack_use, " New") #define rxrpc_congest_modes \ EM(RXRPC_CALL_CONGEST_AVOIDANCE, "CongAvoid") \ From 4272d3034e69aea6e17085ba285d14f5824b430d Mon Sep 17 00:00:00 2001 From: David Howells Date: Mon, 23 Jul 2018 17:18:37 +0100 Subject: [PATCH 07/10] rxrpc: Trace socket notification Trace notifications from the softirq side of the socket to the process-context side. Signed-off-by: David Howells --- include/trace/events/rxrpc.h | 20 ++++++++++++++++++++ net/rxrpc/input.c | 4 +++- 2 files changed, 23 insertions(+), 1 deletion(-) diff --git a/include/trace/events/rxrpc.h b/include/trace/events/rxrpc.h index c1a800a6dee3..196587b8f204 100644 --- a/include/trace/events/rxrpc.h +++ b/include/trace/events/rxrpc.h @@ -1528,6 +1528,26 @@ TRACE_EVENT(rxrpc_call_reset, __entry->tx_seq, __entry->rx_seq) ); +TRACE_EVENT(rxrpc_notify_socket, + TP_PROTO(unsigned int debug_id, rxrpc_serial_t serial), + + TP_ARGS(debug_id, serial), + + TP_STRUCT__entry( + __field(unsigned int, debug_id ) + __field(rxrpc_serial_t, serial ) + ), + + TP_fast_assign( + __entry->debug_id = debug_id; + __entry->serial = serial; + ), + + TP_printk("c=%08x r=%08x", + __entry->debug_id, + __entry->serial) + ); + #endif /* _TRACE_RXRPC_H */ /* This part must be outside protection */ diff --git a/net/rxrpc/input.c b/net/rxrpc/input.c index 8989d760b6b2..cfdc199c6351 100644 --- a/net/rxrpc/input.c +++ b/net/rxrpc/input.c @@ -597,8 +597,10 @@ static void rxrpc_input_data(struct rxrpc_call *call, struct sk_buff *skb, false, true, rxrpc_propose_ack_input_data); - if (sp->hdr.seq == READ_ONCE(call->rx_hard_ack) + 1) + if (sp->hdr.seq == READ_ONCE(call->rx_hard_ack) + 1) { + trace_rxrpc_notify_socket(call->debug_id, serial); rxrpc_notify_socket(call); + } _leave(" [queued]"); } From 4075295ab87670e33eaf98389e319ce84c54c8e4 Mon Sep 17 00:00:00 2001 From: David Howells Date: Mon, 23 Jul 2018 17:18:37 +0100 Subject: [PATCH 08/10] rxrpc: Increase the size of a call's Rx window Increase the size of a call's Rx window from 32 to 63 - ie. one less than the size of the ring buffer. This makes large data transfers perform better when the Tx window on the other side is around 64 (as is the case with Auristor's YFS fileserver). If the server window size is ~32 or smaller, this should make no difference. Signed-off-by: David Howells --- net/rxrpc/ar-internal.h | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/net/rxrpc/ar-internal.h b/net/rxrpc/ar-internal.h index 7eee955a768a..e791d35ee34b 100644 --- a/net/rxrpc/ar-internal.h +++ b/net/rxrpc/ar-internal.h @@ -589,7 +589,7 @@ struct rxrpc_call { */ #define RXRPC_RXTX_BUFF_SIZE 64 #define RXRPC_RXTX_BUFF_MASK (RXRPC_RXTX_BUFF_SIZE - 1) -#define RXRPC_INIT_RX_WINDOW_SIZE 32 +#define RXRPC_INIT_RX_WINDOW_SIZE 63 struct sk_buff **rxtx_buffer; u8 *rxtx_annotations; #define RXRPC_TX_ANNO_ACK 0 From a71a2651bdd3ad9ccae7d8e8c6782727c7ecba98 Mon Sep 17 00:00:00 2001 From: David Howells Date: Mon, 23 Jul 2018 17:18:37 +0100 Subject: [PATCH 09/10] rxrpc: Propose, but don't immediately transmit, the final ACK for a call The final ACK that closes out an rxrpc call needs to be transmitted by the client unless we're going to follow up with a DATA packet for a new call on the same channel (which implicitly ACK's the previous call, thereby saving an ACK). Currently, we don't do that, so if no follow on call is immediately forthcoming, the server will resend the last DATA packet - at which point rxrpc_conn_retransmit_call() will be triggered and will (re)send the final ACK. But the server has to hold on to the last packet until the ACK is received, thereby holding up its resources. Fix the client side to propose a delayed final ACK, to be transmitted after a short delay, assuming the call isn't superseded by a new one. Signed-off-by: David Howells --- net/rxrpc/recvmsg.c | 6 ++---- 1 file changed, 2 insertions(+), 4 deletions(-) diff --git a/net/rxrpc/recvmsg.c b/net/rxrpc/recvmsg.c index 7bff716e911e..02f1f768e16a 100644 --- a/net/rxrpc/recvmsg.c +++ b/net/rxrpc/recvmsg.c @@ -144,13 +144,11 @@ static void rxrpc_end_rx_phase(struct rxrpc_call *call, rxrpc_serial_t serial) trace_rxrpc_receive(call, rxrpc_receive_end, 0, call->rx_top); ASSERTCMP(call->rx_hard_ack, ==, call->rx_top); -#if 0 // TODO: May want to transmit final ACK under some circumstances anyway if (call->state == RXRPC_CALL_CLIENT_RECV_REPLY) { - rxrpc_propose_ACK(call, RXRPC_ACK_IDLE, 0, serial, true, false, + rxrpc_propose_ACK(call, RXRPC_ACK_IDLE, 0, serial, false, true, rxrpc_propose_ack_terminal_ack); - rxrpc_send_ack_packet(call, false, NULL); + //rxrpc_send_ack_packet(call, false, NULL); } -#endif write_lock_bh(&call->state_lock); From d0b35a42031a3107a5735e0d0a605a68f530a96b Mon Sep 17 00:00:00 2001 From: David Howells Date: Mon, 23 Jul 2018 17:18:38 +0100 Subject: [PATCH 10/10] rxrpc: Transmit more ACKs during data reception Immediately flush any outstanding ACK on entry to rxrpc_recvmsg_data() - which transfers data to the target buffers - if we previously had an Rx underrun (ie. we returned -EAGAIN because we ran out of received data). This lets the server know what we've managed to receive something. Also flush any outstanding ACK after calling the function if it hit -EAGAIN to let the server know we processed some data. It might be better to send more ACKs, possibly on a time-based scheme, but that needs some more consideration. With this and some additional AFS patches, it is possible to get large unencrypted O_DIRECT reads to be almost as fast as NFS over TCP. It looks like it might be theoretically possible to improve performance yet more for a server running a single operation as investigation of packet timestamps indicates that the server keeps stalling. The issue appears to be that rxrpc runs in to trouble with ACK packets getting batched together (up to ~32 at a time) somewhere between the IP transmit queue on the client and the ethernet receive queue on the server. However, this case isn't too much of a worry as even a lightly loaded server should be receiving sufficient packet flux to flush the ACK packets to the UDP socket. Signed-off-by: David Howells --- net/rxrpc/ar-internal.h | 1 + net/rxrpc/recvmsg.c | 17 +++++++++++++++++ 2 files changed, 18 insertions(+) diff --git a/net/rxrpc/ar-internal.h b/net/rxrpc/ar-internal.h index e791d35ee34b..9d9278a13d91 100644 --- a/net/rxrpc/ar-internal.h +++ b/net/rxrpc/ar-internal.h @@ -479,6 +479,7 @@ enum rxrpc_call_flag { RXRPC_CALL_RETRANS_TIMEOUT, /* Retransmission due to timeout occurred */ RXRPC_CALL_BEGAN_RX_TIMER, /* We began the expect_rx_by timer */ RXRPC_CALL_RX_HEARD, /* The peer responded at least once to this call */ + RXRPC_CALL_RX_UNDERRUN, /* Got data underrun */ }; /* diff --git a/net/rxrpc/recvmsg.c b/net/rxrpc/recvmsg.c index 02f1f768e16a..a57ea96c84ea 100644 --- a/net/rxrpc/recvmsg.c +++ b/net/rxrpc/recvmsg.c @@ -313,6 +313,10 @@ static int rxrpc_recvmsg_data(struct socket *sock, struct rxrpc_call *call, unsigned int rx_pkt_offset, rx_pkt_len; int ix, copy, ret = -EAGAIN, ret2; + if (test_and_clear_bit(RXRPC_CALL_RX_UNDERRUN, &call->flags) && + call->ackr_reason) + rxrpc_send_ack_packet(call, false, NULL); + rx_pkt_offset = call->rx_pkt_offset; rx_pkt_len = call->rx_pkt_len; @@ -412,6 +416,8 @@ static int rxrpc_recvmsg_data(struct socket *sock, struct rxrpc_call *call, done: trace_rxrpc_recvmsg(call, rxrpc_recvmsg_data_return, seq, rx_pkt_offset, rx_pkt_len, ret); + if (ret == -EAGAIN) + set_bit(RXRPC_CALL_RX_UNDERRUN, &call->flags); return ret; } @@ -684,6 +690,17 @@ int rxrpc_kernel_recv_data(struct socket *sock, struct rxrpc_call *call, read_phase_complete: ret = 1; out: + switch (call->ackr_reason) { + case RXRPC_ACK_IDLE: + break; + case RXRPC_ACK_DELAY: + if (ret != -EAGAIN) + break; + /* Fall through */ + default: + rxrpc_send_ack_packet(call, false, NULL); + } + if (_service) *_service = call->service_id; mutex_unlock(&call->user_mutex);