Commit e867e87a authored by David S. Miller's avatar David S. Miller
Browse files

Merge tag 'rxrpc-rewrite-20160917-2' of...

Merge tag 'rxrpc-rewrite-20160917-2' of git://git.kernel.org/pub/scm/linux/kernel/git/dhowells/linux-fs



David Howells says:

====================
rxrpc: Tracepoint addition and improvement

Here is a set of patches that add some more tracepoints and improve a couple
of existing ones.  New additions include:

 (1) Connection refcount tracking.

 (2) Client connection state machine tracking.

 (3) Tx and Rx packet lifecycle.

 (4) ACK reception and transmission.

 (5) recvmsg processing.

Updates include:

 (1) Print the symbolic packet name in the Rx packet tracepoint.

 (2) Additional call refcount trace events.

 (3) Improvements to sk_buff tracking with AF_RXRPC.

In addition:

 (1) Config option to inject packet loss during both transmission and
     reception.

 (2) Removal of some printks.

This series needs to be applied on top of the previously posted fixes.
====================
Signed-off-by: default avatarDavid S. Miller <davem@davemloft.net>
parents 5b0c6fc8 8a681c36
......@@ -16,6 +16,66 @@
#include <linux/tracepoint.h>
TRACE_EVENT(rxrpc_conn,
TP_PROTO(struct rxrpc_connection *conn, enum rxrpc_conn_trace op,
int usage, const void *where),
TP_ARGS(conn, op, usage, where),
TP_STRUCT__entry(
__field(struct rxrpc_connection *, conn )
__field(int, op )
__field(int, usage )
__field(const void *, where )
),
TP_fast_assign(
__entry->conn = conn;
__entry->op = op;
__entry->usage = usage;
__entry->where = where;
),
TP_printk("C=%p %s u=%d sp=%pSR",
__entry->conn,
rxrpc_conn_traces[__entry->op],
__entry->usage,
__entry->where)
);
TRACE_EVENT(rxrpc_client,
TP_PROTO(struct rxrpc_connection *conn, int channel,
enum rxrpc_client_trace op),
TP_ARGS(conn, channel, op),
TP_STRUCT__entry(
__field(struct rxrpc_connection *, conn )
__field(u32, cid )
__field(int, channel )
__field(int, usage )
__field(enum rxrpc_client_trace, op )
__field(enum rxrpc_conn_cache_state, cs )
),
TP_fast_assign(
__entry->conn = conn;
__entry->channel = channel;
__entry->usage = atomic_read(&conn->usage);
__entry->op = op;
__entry->cid = conn->proto.cid;
__entry->cs = conn->cache_state;
),
TP_printk("C=%p h=%2d %s %s i=%08x u=%d",
__entry->conn,
__entry->channel,
rxrpc_client_traces[__entry->op],
rxrpc_conn_cache_states[__entry->cs],
__entry->cid,
__entry->usage)
);
TRACE_EVENT(rxrpc_call,
TP_PROTO(struct rxrpc_call *call, enum rxrpc_call_trace op,
int usage, const void *where, const void *aux),
......@@ -47,14 +107,14 @@ TRACE_EVENT(rxrpc_call,
);
TRACE_EVENT(rxrpc_skb,
TP_PROTO(struct sk_buff *skb, int op, int usage, int mod_count,
const void *where),
TP_PROTO(struct sk_buff *skb, enum rxrpc_skb_trace op,
int usage, int mod_count, const void *where),
TP_ARGS(skb, op, usage, mod_count, where),
TP_STRUCT__entry(
__field(struct sk_buff *, skb )
__field(int, op )
__field(enum rxrpc_skb_trace, op )
__field(int, usage )
__field(int, mod_count )
__field(const void *, where )
......@@ -70,11 +130,7 @@ TRACE_EVENT(rxrpc_skb,
TP_printk("s=%p %s u=%d m=%d p=%pSR",
__entry->skb,
(__entry->op == 0 ? "NEW" :
__entry->op == 1 ? "SEE" :
__entry->op == 2 ? "GET" :
__entry->op == 3 ? "FRE" :
"PUR"),
rxrpc_skb_traces[__entry->op],
__entry->usage,
__entry->mod_count,
__entry->where)
......@@ -93,11 +149,12 @@ TRACE_EVENT(rxrpc_rx_packet,
memcpy(&__entry->hdr, &sp->hdr, sizeof(__entry->hdr));
),
TP_printk("%08x:%08x:%08x:%04x %08x %08x %02x %02x",
TP_printk("%08x:%08x:%08x:%04x %08x %08x %02x %02x %s",
__entry->hdr.epoch, __entry->hdr.cid,
__entry->hdr.callNumber, __entry->hdr.serviceId,
__entry->hdr.serial, __entry->hdr.seq,
__entry->hdr.type, __entry->hdr.flags)
__entry->hdr.type, __entry->hdr.flags,
__entry->hdr.type <= 15 ? rxrpc_pkts[__entry->hdr.type] : "?UNK")
);
TRACE_EVENT(rxrpc_rx_done,
......@@ -147,6 +204,155 @@ TRACE_EVENT(rxrpc_abort,
__entry->abort_code, __entry->error, __entry->why)
);
TRACE_EVENT(rxrpc_transmit,
TP_PROTO(struct rxrpc_call *call, enum rxrpc_transmit_trace why),
TP_ARGS(call, why),
TP_STRUCT__entry(
__field(struct rxrpc_call *, call )
__field(enum rxrpc_transmit_trace, why )
__field(rxrpc_seq_t, tx_hard_ack )
__field(rxrpc_seq_t, tx_top )
),
TP_fast_assign(
__entry->call = call;
__entry->why = why;
__entry->tx_hard_ack = call->tx_hard_ack;
__entry->tx_top = call->tx_top;
),
TP_printk("c=%p %s f=%08x n=%u",
__entry->call,
rxrpc_transmit_traces[__entry->why],
__entry->tx_hard_ack + 1,
__entry->tx_top - __entry->tx_hard_ack)
);
TRACE_EVENT(rxrpc_rx_ack,
TP_PROTO(struct rxrpc_call *call, rxrpc_seq_t first, u8 reason, u8 n_acks),
TP_ARGS(call, first, reason, n_acks),
TP_STRUCT__entry(
__field(struct rxrpc_call *, call )
__field(rxrpc_seq_t, first )
__field(u8, reason )
__field(u8, n_acks )
),
TP_fast_assign(
__entry->call = call;
__entry->first = first;
__entry->reason = reason;
__entry->n_acks = n_acks;
),
TP_printk("c=%p %s f=%08x n=%u",
__entry->call,
rxrpc_acks(__entry->reason),
__entry->first,
__entry->n_acks)
);
TRACE_EVENT(rxrpc_tx_ack,
TP_PROTO(struct rxrpc_call *call, rxrpc_seq_t first,
rxrpc_serial_t serial, u8 reason, u8 n_acks),
TP_ARGS(call, first, serial, reason, n_acks),
TP_STRUCT__entry(
__field(struct rxrpc_call *, call )
__field(rxrpc_seq_t, first )
__field(rxrpc_serial_t, serial )
__field(u8, reason )
__field(u8, n_acks )
),
TP_fast_assign(
__entry->call = call;
__entry->first = first;
__entry->serial = serial;
__entry->reason = reason;
__entry->n_acks = n_acks;
),
TP_printk("c=%p %s f=%08x r=%08x n=%u",
__entry->call,
rxrpc_acks(__entry->reason),
__entry->first,
__entry->serial,
__entry->n_acks)
);
TRACE_EVENT(rxrpc_receive,
TP_PROTO(struct rxrpc_call *call, enum rxrpc_receive_trace why,
rxrpc_serial_t serial, rxrpc_seq_t seq),
TP_ARGS(call, why, serial, seq),
TP_STRUCT__entry(
__field(struct rxrpc_call *, call )
__field(enum rxrpc_receive_trace, why )
__field(rxrpc_serial_t, serial )
__field(rxrpc_seq_t, seq )
__field(rxrpc_seq_t, hard_ack )
__field(rxrpc_seq_t, top )
),
TP_fast_assign(
__entry->call = call;
__entry->why = why;
__entry->serial = serial;
__entry->seq = seq;
__entry->hard_ack = call->rx_hard_ack;
__entry->top = call->rx_top;
),
TP_printk("c=%p %s r=%08x q=%08x w=%08x-%08x",
__entry->call,
rxrpc_receive_traces[__entry->why],
__entry->serial,
__entry->seq,
__entry->hard_ack,
__entry->top)
);
TRACE_EVENT(rxrpc_recvmsg,
TP_PROTO(struct rxrpc_call *call, enum rxrpc_recvmsg_trace why,
rxrpc_seq_t seq, unsigned int offset, unsigned int len,
int ret),
TP_ARGS(call, why, seq, offset, len, ret),
TP_STRUCT__entry(
__field(struct rxrpc_call *, call )
__field(enum rxrpc_recvmsg_trace, why )
__field(rxrpc_seq_t, seq )
__field(unsigned int, offset )
__field(unsigned int, len )
__field(int, ret )
),
TP_fast_assign(
__entry->call = call;
__entry->why = why;
__entry->seq = seq;
__entry->offset = offset;
__entry->len = len;
__entry->ret = ret;
),
TP_printk("c=%p %s q=%08x o=%u l=%u ret=%d",
__entry->call,
rxrpc_recvmsg_traces[__entry->why],
__entry->seq,
__entry->offset,
__entry->len,
__entry->ret)
);
#endif /* _TRACE_RXRPC_H */
/* This part must be outside protection */
......
......@@ -26,6 +26,13 @@ config AF_RXRPC_IPV6
Say Y here to allow AF_RXRPC to use IPV6 UDP as well as IPV4 UDP as
its network transport.
config AF_RXRPC_INJECT_LOSS
bool "Inject packet loss into RxRPC packet stream"
depends on AF_RXRPC
help
Say Y here to inject packet loss by discarding some received and some
transmitted packets.
config AF_RXRPC_DEBUG
bool "RxRPC dynamic debugging"
......
......@@ -45,7 +45,7 @@ u32 rxrpc_epoch;
atomic_t rxrpc_debug_id;
/* count of skbs currently in use */
atomic_t rxrpc_n_skbs;
atomic_t rxrpc_n_tx_skbs, rxrpc_n_rx_skbs;
struct workqueue_struct *rxrpc_workqueue;
......@@ -867,7 +867,8 @@ static void __exit af_rxrpc_exit(void)
proto_unregister(&rxrpc_proto);
rxrpc_destroy_all_calls();
rxrpc_destroy_all_connections();
ASSERTCMP(atomic_read(&rxrpc_n_skbs), ==, 0);
ASSERTCMP(atomic_read(&rxrpc_n_tx_skbs), ==, 0);
ASSERTCMP(atomic_read(&rxrpc_n_rx_skbs), ==, 0);
rxrpc_destroy_all_locals();
remove_proc_entry("rxrpc_conns", init_net.proc_net);
......
......@@ -314,6 +314,7 @@ enum rxrpc_conn_cache_state {
RXRPC_CONN_CLIENT_ACTIVE, /* Conn is on active list, doing calls */
RXRPC_CONN_CLIENT_CULLED, /* Conn is culled and delisted, doing calls */
RXRPC_CONN_CLIENT_IDLE, /* Conn is on idle list, doing mostly nothing */
RXRPC_CONN__NR_CACHE_STATES
};
/*
......@@ -519,6 +520,7 @@ struct rxrpc_call {
rxrpc_seq_t rx_expect_next; /* Expected next packet sequence number */
u8 rx_winsize; /* Size of Rx window */
u8 tx_winsize; /* Maximum size of Tx window */
bool tx_phase; /* T if transmission phase, F if receive phase */
u8 nr_jumbo_bad; /* Number of jumbo dups/exceeds-windows */
/* receive-phase ACK management */
......@@ -533,12 +535,73 @@ struct rxrpc_call {
rxrpc_serial_t acks_latest; /* serial number of latest ACK received */
};
enum rxrpc_skb_trace {
rxrpc_skb_rx_cleaned,
rxrpc_skb_rx_freed,
rxrpc_skb_rx_got,
rxrpc_skb_rx_lost,
rxrpc_skb_rx_received,
rxrpc_skb_rx_rotated,
rxrpc_skb_rx_purged,
rxrpc_skb_rx_seen,
rxrpc_skb_tx_cleaned,
rxrpc_skb_tx_freed,
rxrpc_skb_tx_got,
rxrpc_skb_tx_lost,
rxrpc_skb_tx_new,
rxrpc_skb_tx_rotated,
rxrpc_skb_tx_seen,
rxrpc_skb__nr_trace
};
extern const char rxrpc_skb_traces[rxrpc_skb__nr_trace][7];
enum rxrpc_conn_trace {
rxrpc_conn_new_client,
rxrpc_conn_new_service,
rxrpc_conn_queued,
rxrpc_conn_seen,
rxrpc_conn_got,
rxrpc_conn_put_client,
rxrpc_conn_put_service,
rxrpc_conn__nr_trace
};
extern const char rxrpc_conn_traces[rxrpc_conn__nr_trace][4];
enum rxrpc_client_trace {
rxrpc_client_activate_chans,
rxrpc_client_alloc,
rxrpc_client_chan_activate,
rxrpc_client_chan_disconnect,
rxrpc_client_chan_pass,
rxrpc_client_chan_unstarted,
rxrpc_client_cleanup,
rxrpc_client_count,
rxrpc_client_discard,
rxrpc_client_duplicate,
rxrpc_client_exposed,
rxrpc_client_replace,
rxrpc_client_to_active,
rxrpc_client_to_culled,
rxrpc_client_to_idle,
rxrpc_client_to_inactive,
rxrpc_client_to_waiting,
rxrpc_client_uncount,
rxrpc_client__nr_trace
};
extern const char rxrpc_client_traces[rxrpc_client__nr_trace][7];
extern const char rxrpc_conn_cache_states[RXRPC_CONN__NR_CACHE_STATES][5];
enum rxrpc_call_trace {
rxrpc_call_new_client,
rxrpc_call_new_service,
rxrpc_call_queued,
rxrpc_call_queued_ref,
rxrpc_call_seen,
rxrpc_call_connected,
rxrpc_call_release,
rxrpc_call_got,
rxrpc_call_got_userid,
rxrpc_call_got_kernel,
......@@ -546,17 +609,62 @@ enum rxrpc_call_trace {
rxrpc_call_put_userid,
rxrpc_call_put_kernel,
rxrpc_call_put_noqueue,
rxrpc_call_error,
rxrpc_call__nr_trace
};
extern const char rxrpc_call_traces[rxrpc_call__nr_trace][4];
enum rxrpc_transmit_trace {
rxrpc_transmit_wait,
rxrpc_transmit_queue,
rxrpc_transmit_queue_reqack,
rxrpc_transmit_queue_last,
rxrpc_transmit_rotate,
rxrpc_transmit_end,
rxrpc_transmit__nr_trace
};
extern const char rxrpc_transmit_traces[rxrpc_transmit__nr_trace][4];
enum rxrpc_receive_trace {
rxrpc_receive_incoming,
rxrpc_receive_queue,
rxrpc_receive_queue_last,
rxrpc_receive_front,
rxrpc_receive_rotate,
rxrpc_receive_end,
rxrpc_receive__nr_trace
};
extern const char rxrpc_receive_traces[rxrpc_receive__nr_trace][4];
enum rxrpc_recvmsg_trace {
rxrpc_recvmsg_enter,
rxrpc_recvmsg_wait,
rxrpc_recvmsg_dequeue,
rxrpc_recvmsg_hole,
rxrpc_recvmsg_next,
rxrpc_recvmsg_cont,
rxrpc_recvmsg_full,
rxrpc_recvmsg_data_return,
rxrpc_recvmsg_terminal,
rxrpc_recvmsg_to_be_accepted,
rxrpc_recvmsg_return,
rxrpc_recvmsg__nr_trace
};
extern const char rxrpc_recvmsg_traces[rxrpc_recvmsg__nr_trace][5];
extern const char *const rxrpc_pkts[];
extern const char *rxrpc_acks(u8 reason);
#include <trace/events/rxrpc.h>
/*
* af_rxrpc.c
*/
extern atomic_t rxrpc_n_skbs;
extern atomic_t rxrpc_n_tx_skbs, rxrpc_n_rx_skbs;
extern u32 rxrpc_epoch;
extern atomic_t rxrpc_debug_id;
extern struct workqueue_struct *rxrpc_workqueue;
......@@ -728,7 +836,11 @@ struct rxrpc_connection *rxrpc_find_connection_rcu(struct rxrpc_local *,
void __rxrpc_disconnect_call(struct rxrpc_connection *, struct rxrpc_call *);
void rxrpc_disconnect_call(struct rxrpc_call *);
void rxrpc_kill_connection(struct rxrpc_connection *);
void __rxrpc_put_connection(struct rxrpc_connection *);
bool rxrpc_queue_conn(struct rxrpc_connection *);
void rxrpc_see_connection(struct rxrpc_connection *);
void rxrpc_get_connection(struct rxrpc_connection *);
struct rxrpc_connection *rxrpc_get_connection_maybe(struct rxrpc_connection *);
void rxrpc_put_service_conn(struct rxrpc_connection *);
void __exit rxrpc_destroy_all_connections(void);
static inline bool rxrpc_conn_is_client(const struct rxrpc_connection *conn)
......@@ -741,38 +853,15 @@ static inline bool rxrpc_conn_is_service(const struct rxrpc_connection *conn)
return !rxrpc_conn_is_client(conn);
}
static inline void rxrpc_get_connection(struct rxrpc_connection *conn)
{
atomic_inc(&conn->usage);
}
static inline
struct rxrpc_connection *rxrpc_get_connection_maybe(struct rxrpc_connection *conn)
{
return atomic_inc_not_zero(&conn->usage) ? conn : NULL;
}
static inline void rxrpc_put_connection(struct rxrpc_connection *conn)
{
if (!conn)
return;
if (rxrpc_conn_is_client(conn)) {
if (atomic_dec_and_test(&conn->usage))
rxrpc_put_client_conn(conn);
} else {
if (atomic_dec_return(&conn->usage) == 1)
__rxrpc_put_connection(conn);
}
}
static inline bool rxrpc_queue_conn(struct rxrpc_connection *conn)
{
if (!rxrpc_get_connection_maybe(conn))
return false;
if (!rxrpc_queue_work(&conn->processor))
rxrpc_put_connection(conn);
return true;
if (rxrpc_conn_is_client(conn))
rxrpc_put_client_conn(conn);
else
rxrpc_put_service_conn(conn);
}
/*
......@@ -851,11 +940,8 @@ extern unsigned int rxrpc_rx_mtu;
extern unsigned int rxrpc_rx_jumbo_max;
extern unsigned int rxrpc_resend_timeout;
extern const char *const rxrpc_pkts[];
extern const s8 rxrpc_ack_priority[];
extern const char *rxrpc_acks(u8 reason);
/*
* output.c
*/
......@@ -936,10 +1022,11 @@ int rxrpc_do_sendmsg(struct rxrpc_sock *, struct msghdr *, size_t);
*/
void rxrpc_kernel_data_consumed(struct rxrpc_call *, struct sk_buff *);
void rxrpc_packet_destructor(struct sk_buff *);
void rxrpc_new_skb(struct sk_buff *);
void rxrpc_see_skb(struct sk_buff *);
void rxrpc_get_skb(struct sk_buff *);
void rxrpc_free_skb(struct sk_buff *);
void rxrpc_new_skb(struct sk_buff *, enum rxrpc_skb_trace);
void rxrpc_see_skb(struct sk_buff *, enum rxrpc_skb_trace);
void rxrpc_get_skb(struct sk_buff *, enum rxrpc_skb_trace);
void rxrpc_free_skb(struct sk_buff *, enum rxrpc_skb_trace);
void rxrpc_lose_skb(struct sk_buff *, enum rxrpc_skb_trace);
void rxrpc_purge_queue(struct sk_buff_head *);
/*
......
......@@ -85,6 +85,9 @@ static int rxrpc_service_prealloc_one(struct rxrpc_sock *rx,
b->conn_backlog[head] = conn;
smp_store_release(&b->conn_backlog_head,
(head + 1) & (size - 1));
trace_rxrpc_conn(conn, rxrpc_conn_new_service,
atomic_read(&conn->usage), here);
}
/* Now it gets complicated, because calls get registered with the
......@@ -290,6 +293,7 @@ static struct rxrpc_call *rxrpc_alloc_incoming_call(struct rxrpc_sock *rx,
rxrpc_get_local(local);
conn->params.local = local;
conn->params.peer = peer;
rxrpc_see_connection(conn);
rxrpc_new_incoming_connection(conn, skb);
} else {
rxrpc_get_connection(conn);
......@@ -363,6 +367,9 @@ struct rxrpc_call *rxrpc_new_incoming_call(struct rxrpc_local *local,
goto out;
}
trace_rxrpc_receive(call, rxrpc_receive_incoming,
sp->hdr.serial, sp->hdr.seq);
/* Make the call live. */
rxrpc_incoming_call(rx, call, skb);
conn = call->conn;
......
......@@ -170,7 +170,7 @@ static void rxrpc_resend(struct rxrpc_call *call)
continue;
skb = call->rxtx_buffer[ix];
rxrpc_see_skb(skb);
rxrpc_see_skb(skb, rxrpc_skb_tx_seen);
sp = rxrpc_skb(skb);
if (annotation == RXRPC_TX_ANNO_UNACK) {
......@@ -199,7 +199,7 @@ static void rxrpc_resend(struct rxrpc_call *call)
continue;
skb = call->rxtx_buffer[ix];
rxrpc_get_skb(skb);
rxrpc_get_skb(skb, rxrpc_skb_tx_got);
spin_unlock_bh(&call->lock);
sp = rxrpc_skb(skb);
......@@ -211,7 +211,7 @@ static void rxrpc_resend(struct rxrpc_call *call)
if (rxrpc_send_data_packet(call->conn, skb) < 0) {
call->resend_at = now + 2;
rxrpc_free_skb(skb);
rxrpc_free_skb(skb, rxrpc_skb_tx_freed);
return;
}
......@@ -219,7 +219,7 @@ static void rxrpc_resend(struct rxrpc_call *call)
rxrpc_expose_client_call(call);
sp->resend_at = now + rxrpc_resend_timeout;
rxrpc_free_skb(skb);
rxrpc_free_skb(skb, rxrpc_skb_tx_freed);
spin_lock_bh(&call->lock);
/* We need to clear the retransmit state, but there are two
......
......@@ -53,6 +53,8 @@ const char rxrpc_call_traces[rxrpc_call__nr_trace][4] = {
[rxrpc_call_new_service] = "NWs",
[rxrpc_call_queued] = "QUE",
[rxrpc_call_queued_ref] = "QUR",
[rxrpc_call_connected] = "CON",
[rxrpc_call_release] = "RLS",
[rxrpc_call_seen] = "SEE",
[rxrpc_call_got] = "GOT",
[rxrpc_call_got_userid] = "Gus",
......@@ -61,6 +63,7 @@ const char rxrpc_call_traces[rxrpc_call__nr_trace][4] = {
[rxrpc_call_put_userid] = "Pus",
[rxrpc_call_put_kernel] = "Pke",
[rxrpc_call_put_noqueue] = "PNQ",
[rxrpc_call_error] = "*E*",
};
struct kmem_cache *rxrpc_call_jar;
......@@ -179,6 +182,7 @@ static struct rxrpc_call *rxrpc_alloc_client_call(struct sockaddr_rxrpc *srx,
return ERR_PTR(-ENOMEM);
call->state = RXRPC_CALL_CLIENT_AWAIT_CONN;
call->service_id = srx->srx_service;
call->tx_phase = true;
_leave(" = %p", call);
return call;
......@@ -222,8 +226,8 @@ struct rxrpc_call *rxrpc_new_client_call(struct rxrpc_sock *rx,
return call;
}
trace_rxrpc_call(call, 0, atomic_read(&call->usage),