rxrpc: Improve the call tracking tracepoint

Improve the call tracking tracepoint by showing more differentiation
between some of the put and get events, including:

  (1) Getting and putting refs for the socket call user ID tree.

  (2) Getting and putting refs for queueing and failing to queue the call
      processor work item.

Note that these aren't necessarily used in this patch, but will be taken
advantage of in future patches.

An enum is added for the event subtype numbers rather than coding them
directly as decimal numbers and a table of 3-letter strings is provided
rather than a sequence of ?: operators.

Signed-off-by: David Howells <dhowells@redhat.com>
This commit is contained in:
David Howells 2016-09-07 14:34:21 +01:00
parent e796cb4192
commit fff72429c2
10 changed files with 79 additions and 51 deletions

View File

@ -17,7 +17,8 @@
#include <linux/tracepoint.h> #include <linux/tracepoint.h>
TRACE_EVENT(rxrpc_call, TRACE_EVENT(rxrpc_call,
TP_PROTO(struct rxrpc_call *call, int op, int usage, int nskb, TP_PROTO(struct rxrpc_call *call, enum rxrpc_call_trace op,
int usage, int nskb,
const void *where, const void *aux), const void *where, const void *aux),
TP_ARGS(call, op, usage, nskb, where, aux), TP_ARGS(call, op, usage, nskb, where, aux),
@ -42,13 +43,7 @@ TRACE_EVENT(rxrpc_call,
TP_printk("c=%p %s u=%d s=%d p=%pSR a=%p", TP_printk("c=%p %s u=%d s=%d p=%pSR a=%p",
__entry->call, __entry->call,
(__entry->op == 0 ? "NWc" : rxrpc_call_traces[__entry->op],
__entry->op == 1 ? "NWs" :
__entry->op == 2 ? "SEE" :
__entry->op == 3 ? "GET" :
__entry->op == 4 ? "Gsb" :
__entry->op == 5 ? "PUT" :
"Psb"),
__entry->usage, __entry->usage,
__entry->nskb, __entry->nskb,
__entry->where, __entry->where,

View File

@ -296,7 +296,7 @@ void rxrpc_kernel_end_call(struct socket *sock, struct rxrpc_call *call)
_enter("%d{%d}", call->debug_id, atomic_read(&call->usage)); _enter("%d{%d}", call->debug_id, atomic_read(&call->usage));
rxrpc_remove_user_ID(rxrpc_sk(sock->sk), call); rxrpc_remove_user_ID(rxrpc_sk(sock->sk), call);
rxrpc_purge_queue(&call->knlrecv_queue); rxrpc_purge_queue(&call->knlrecv_queue);
rxrpc_put_call(call); rxrpc_put_call(call, rxrpc_call_put);
} }
EXPORT_SYMBOL(rxrpc_kernel_end_call); EXPORT_SYMBOL(rxrpc_kernel_end_call);

View File

@ -508,6 +508,24 @@ struct rxrpc_call {
unsigned long ackr_window[RXRPC_ACKR_WINDOW_ASZ + 1]; unsigned long ackr_window[RXRPC_ACKR_WINDOW_ASZ + 1];
}; };
enum rxrpc_call_trace {
rxrpc_call_new_client,
rxrpc_call_new_service,
rxrpc_call_queued,
rxrpc_call_queued_ref,
rxrpc_call_seen,
rxrpc_call_got,
rxrpc_call_got_skb,
rxrpc_call_got_userid,
rxrpc_call_put,
rxrpc_call_put_skb,
rxrpc_call_put_userid,
rxrpc_call_put_noqueue,
rxrpc_call__nr_trace
};
extern const char rxrpc_call_traces[rxrpc_call__nr_trace][4];
#include <trace/events/rxrpc.h> #include <trace/events/rxrpc.h>
/* /*
@ -555,8 +573,8 @@ struct rxrpc_call *rxrpc_incoming_call(struct rxrpc_sock *,
void rxrpc_release_call(struct rxrpc_call *); void rxrpc_release_call(struct rxrpc_call *);
void rxrpc_release_calls_on_socket(struct rxrpc_sock *); void rxrpc_release_calls_on_socket(struct rxrpc_sock *);
void rxrpc_see_call(struct rxrpc_call *); void rxrpc_see_call(struct rxrpc_call *);
void rxrpc_get_call(struct rxrpc_call *); void rxrpc_get_call(struct rxrpc_call *, enum rxrpc_call_trace);
void rxrpc_put_call(struct rxrpc_call *); void rxrpc_put_call(struct rxrpc_call *, enum rxrpc_call_trace);
void rxrpc_get_call_for_skb(struct rxrpc_call *, struct sk_buff *); void rxrpc_get_call_for_skb(struct rxrpc_call *, struct sk_buff *);
void rxrpc_put_call_for_skb(struct rxrpc_call *, struct sk_buff *); void rxrpc_put_call_for_skb(struct rxrpc_call *, struct sk_buff *);
void __exit rxrpc_destroy_all_calls(void); void __exit rxrpc_destroy_all_calls(void);

View File

@ -115,7 +115,7 @@ static int rxrpc_accept_incoming_call(struct rxrpc_local *local,
write_lock(&rx->call_lock); write_lock(&rx->call_lock);
if (!test_and_set_bit(RXRPC_CALL_INIT_ACCEPT, &call->flags)) { if (!test_and_set_bit(RXRPC_CALL_INIT_ACCEPT, &call->flags)) {
rxrpc_get_call(call); rxrpc_get_call(call, rxrpc_call_got);
spin_lock(&call->conn->state_lock); spin_lock(&call->conn->state_lock);
if (sp->hdr.securityIndex > 0 && if (sp->hdr.securityIndex > 0 &&
@ -155,7 +155,7 @@ static int rxrpc_accept_incoming_call(struct rxrpc_local *local,
_debug("done"); _debug("done");
read_unlock_bh(&local->services_lock); read_unlock_bh(&local->services_lock);
rxrpc_free_skb(notification); rxrpc_free_skb(notification);
rxrpc_put_call(call); rxrpc_put_call(call, rxrpc_call_put);
_leave(" = 0"); _leave(" = 0");
return 0; return 0;
@ -166,11 +166,11 @@ invalid_service:
read_lock_bh(&call->state_lock); read_lock_bh(&call->state_lock);
if (!test_bit(RXRPC_CALL_RELEASED, &call->flags) && if (!test_bit(RXRPC_CALL_RELEASED, &call->flags) &&
!test_and_set_bit(RXRPC_CALL_EV_RELEASE, &call->events)) { !test_and_set_bit(RXRPC_CALL_EV_RELEASE, &call->events)) {
rxrpc_get_call(call); rxrpc_get_call(call, rxrpc_call_got);
rxrpc_queue_call(call); rxrpc_queue_call(call);
} }
read_unlock_bh(&call->state_lock); read_unlock_bh(&call->state_lock);
rxrpc_put_call(call); rxrpc_put_call(call, rxrpc_call_put);
ret = -ECONNREFUSED; ret = -ECONNREFUSED;
error: error:
rxrpc_free_skb(notification); rxrpc_free_skb(notification);
@ -341,6 +341,7 @@ struct rxrpc_call *rxrpc_accept_call(struct rxrpc_sock *rx,
} }
/* formalise the acceptance */ /* formalise the acceptance */
rxrpc_get_call(call, rxrpc_call_got_userid);
call->notify_rx = notify_rx; call->notify_rx = notify_rx;
call->user_call_ID = user_call_ID; call->user_call_ID = user_call_ID;
rb_link_node(&call->sock_node, parent, pp); rb_link_node(&call->sock_node, parent, pp);
@ -351,7 +352,6 @@ struct rxrpc_call *rxrpc_accept_call(struct rxrpc_sock *rx,
BUG(); BUG();
rxrpc_queue_call(call); rxrpc_queue_call(call);
rxrpc_get_call(call);
write_unlock_bh(&call->state_lock); write_unlock_bh(&call->state_lock);
write_unlock(&rx->call_lock); write_unlock(&rx->call_lock);
_leave(" = %p{%d}", call, call->debug_id); _leave(" = %p{%d}", call, call->debug_id);

View File

@ -1246,7 +1246,7 @@ send_message_2:
kill_ACKs: kill_ACKs:
del_timer_sync(&call->ack_timer); del_timer_sync(&call->ack_timer);
if (test_and_clear_bit(RXRPC_CALL_EV_ACK_FINAL, &call->events)) if (test_and_clear_bit(RXRPC_CALL_EV_ACK_FINAL, &call->events))
rxrpc_put_call(call); rxrpc_put_call(call, rxrpc_call_put);
clear_bit(RXRPC_CALL_EV_ACK, &call->events); clear_bit(RXRPC_CALL_EV_ACK, &call->events);
maybe_reschedule: maybe_reschedule:

View File

@ -55,6 +55,21 @@ const char *const rxrpc_call_completions[NR__RXRPC_CALL_COMPLETIONS] = {
[RXRPC_CALL_NETWORK_ERROR] = "NetError", [RXRPC_CALL_NETWORK_ERROR] = "NetError",
}; };
const char rxrpc_call_traces[rxrpc_call__nr_trace][4] = {
[rxrpc_call_new_client] = "NWc",
[rxrpc_call_new_service] = "NWs",
[rxrpc_call_queued] = "QUE",
[rxrpc_call_queued_ref] = "QUR",
[rxrpc_call_seen] = "SEE",
[rxrpc_call_got] = "GOT",
[rxrpc_call_got_skb] = "Gsk",
[rxrpc_call_got_userid] = "Gus",
[rxrpc_call_put] = "PUT",
[rxrpc_call_put_skb] = "Psk",
[rxrpc_call_put_userid] = "Pus",
[rxrpc_call_put_noqueue] = "PNQ",
};
struct kmem_cache *rxrpc_call_jar; struct kmem_cache *rxrpc_call_jar;
LIST_HEAD(rxrpc_calls); LIST_HEAD(rxrpc_calls);
DEFINE_RWLOCK(rxrpc_call_lock); DEFINE_RWLOCK(rxrpc_call_lock);
@ -96,7 +111,7 @@ struct rxrpc_call *rxrpc_find_call_by_user_ID(struct rxrpc_sock *rx,
return NULL; return NULL;
found_extant_call: found_extant_call:
rxrpc_get_call(call); rxrpc_get_call(call, rxrpc_call_got);
read_unlock(&rx->call_lock); read_unlock(&rx->call_lock);
_leave(" = %p [%d]", call, atomic_read(&call->usage)); _leave(" = %p [%d]", call, atomic_read(&call->usage));
return call; return call;
@ -252,8 +267,7 @@ struct rxrpc_call *rxrpc_new_client_call(struct rxrpc_sock *rx,
goto found_user_ID_now_present; goto found_user_ID_now_present;
} }
rxrpc_get_call(call); rxrpc_get_call(call, rxrpc_call_got_userid);
rb_link_node(&call->sock_node, parent, pp); rb_link_node(&call->sock_node, parent, pp);
rb_insert_color(&call->sock_node, &rx->calls); rb_insert_color(&call->sock_node, &rx->calls);
write_unlock(&rx->call_lock); write_unlock(&rx->call_lock);
@ -275,7 +289,7 @@ error:
write_lock(&rx->call_lock); write_lock(&rx->call_lock);
rb_erase(&call->sock_node, &rx->calls); rb_erase(&call->sock_node, &rx->calls);
write_unlock(&rx->call_lock); write_unlock(&rx->call_lock);
rxrpc_put_call(call); rxrpc_put_call(call, rxrpc_call_put_userid);
write_lock_bh(&rxrpc_call_lock); write_lock_bh(&rxrpc_call_lock);
list_del_init(&call->link); list_del_init(&call->link);
@ -283,7 +297,7 @@ error:
set_bit(RXRPC_CALL_RELEASED, &call->flags); set_bit(RXRPC_CALL_RELEASED, &call->flags);
call->state = RXRPC_CALL_DEAD; call->state = RXRPC_CALL_DEAD;
rxrpc_put_call(call); rxrpc_put_call(call, rxrpc_call_put);
_leave(" = %d", ret); _leave(" = %d", ret);
return ERR_PTR(ret); return ERR_PTR(ret);
@ -296,7 +310,7 @@ found_user_ID_now_present:
write_unlock(&rx->call_lock); write_unlock(&rx->call_lock);
set_bit(RXRPC_CALL_RELEASED, &call->flags); set_bit(RXRPC_CALL_RELEASED, &call->flags);
call->state = RXRPC_CALL_DEAD; call->state = RXRPC_CALL_DEAD;
rxrpc_put_call(call); rxrpc_put_call(call, rxrpc_call_put);
_leave(" = -EEXIST [%p]", call); _leave(" = -EEXIST [%p]", call);
return ERR_PTR(-EEXIST); return ERR_PTR(-EEXIST);
} }
@ -322,8 +336,8 @@ struct rxrpc_call *rxrpc_incoming_call(struct rxrpc_sock *rx,
if (!candidate) if (!candidate)
return ERR_PTR(-EBUSY); return ERR_PTR(-EBUSY);
trace_rxrpc_call(candidate, 1, atomic_read(&candidate->usage), trace_rxrpc_call(candidate, rxrpc_call_new_service,
0, here, NULL); atomic_read(&candidate->usage), 0, here, NULL);
chan = sp->hdr.cid & RXRPC_CHANNELMASK; chan = sp->hdr.cid & RXRPC_CHANNELMASK;
candidate->socket = rx; candidate->socket = rx;
@ -358,7 +372,7 @@ struct rxrpc_call *rxrpc_incoming_call(struct rxrpc_sock *rx,
read_unlock(&call->state_lock); read_unlock(&call->state_lock);
goto aborted_call; goto aborted_call;
default: default:
rxrpc_get_call(call); rxrpc_get_call(call, rxrpc_call_got);
read_unlock(&call->state_lock); read_unlock(&call->state_lock);
goto extant_call; goto extant_call;
} }
@ -447,20 +461,20 @@ void rxrpc_see_call(struct rxrpc_call *call)
int n = atomic_read(&call->usage); int n = atomic_read(&call->usage);
int m = atomic_read(&call->skb_count); int m = atomic_read(&call->skb_count);
trace_rxrpc_call(call, 2, n, m, here, 0); trace_rxrpc_call(call, rxrpc_call_seen, n, m, here, NULL);
} }
} }
/* /*
* Note the addition of a ref on a call. * Note the addition of a ref on a call.
*/ */
void rxrpc_get_call(struct rxrpc_call *call) void rxrpc_get_call(struct rxrpc_call *call, enum rxrpc_call_trace op)
{ {
const void *here = __builtin_return_address(0); const void *here = __builtin_return_address(0);
int n = atomic_inc_return(&call->usage); int n = atomic_inc_return(&call->usage);
int m = atomic_read(&call->skb_count); int m = atomic_read(&call->skb_count);
trace_rxrpc_call(call, 3, n, m, here, 0); trace_rxrpc_call(call, op, n, m, here, NULL);
} }
/* /*
@ -472,7 +486,7 @@ void rxrpc_get_call_for_skb(struct rxrpc_call *call, struct sk_buff *skb)
int n = atomic_inc_return(&call->usage); int n = atomic_inc_return(&call->usage);
int m = atomic_inc_return(&call->skb_count); int m = atomic_inc_return(&call->skb_count);
trace_rxrpc_call(call, 4, n, m, here, skb); trace_rxrpc_call(call, rxrpc_call_got_skb, n, m, here, skb);
} }
/* /*
@ -575,7 +589,7 @@ static void rxrpc_dead_call_expired(unsigned long _call)
write_lock_bh(&call->state_lock); write_lock_bh(&call->state_lock);
call->state = RXRPC_CALL_DEAD; call->state = RXRPC_CALL_DEAD;
write_unlock_bh(&call->state_lock); write_unlock_bh(&call->state_lock);
rxrpc_put_call(call); rxrpc_put_call(call, rxrpc_call_put);
} }
/* /*
@ -632,7 +646,7 @@ void rxrpc_release_calls_on_socket(struct rxrpc_sock *rx)
/* /*
* release a call * release a call
*/ */
void rxrpc_put_call(struct rxrpc_call *call) void rxrpc_put_call(struct rxrpc_call *call, enum rxrpc_call_trace op)
{ {
const void *here = __builtin_return_address(0); const void *here = __builtin_return_address(0);
int n, m; int n, m;
@ -641,7 +655,7 @@ void rxrpc_put_call(struct rxrpc_call *call)
n = atomic_dec_return(&call->usage); n = atomic_dec_return(&call->usage);
m = atomic_read(&call->skb_count); m = atomic_read(&call->skb_count);
trace_rxrpc_call(call, 5, n, m, here, NULL); trace_rxrpc_call(call, op, n, m, here, NULL);
ASSERTCMP(n, >=, 0); ASSERTCMP(n, >=, 0);
if (n == 0) { if (n == 0) {
_debug("call %d dead", call->debug_id); _debug("call %d dead", call->debug_id);
@ -661,7 +675,7 @@ void rxrpc_put_call_for_skb(struct rxrpc_call *call, struct sk_buff *skb)
n = atomic_dec_return(&call->usage); n = atomic_dec_return(&call->usage);
m = atomic_dec_return(&call->skb_count); m = atomic_dec_return(&call->skb_count);
trace_rxrpc_call(call, 6, n, m, here, skb); trace_rxrpc_call(call, rxrpc_call_put_skb, n, m, here, skb);
ASSERTCMP(n, >=, 0); ASSERTCMP(n, >=, 0);
if (n == 0) { if (n == 0) {
_debug("call %d dead", call->debug_id); _debug("call %d dead", call->debug_id);

View File

@ -537,7 +537,7 @@ static void rxrpc_post_packet_to_call(struct rxrpc_call *call,
} }
read_unlock(&call->state_lock); read_unlock(&call->state_lock);
rxrpc_get_call(call); rxrpc_get_call(call, rxrpc_call_got);
if (sp->hdr.type == RXRPC_PACKET_TYPE_DATA && if (sp->hdr.type == RXRPC_PACKET_TYPE_DATA &&
sp->hdr.flags & RXRPC_JUMBO_PACKET) sp->hdr.flags & RXRPC_JUMBO_PACKET)
@ -545,12 +545,12 @@ static void rxrpc_post_packet_to_call(struct rxrpc_call *call,
else else
rxrpc_fast_process_packet(call, skb); rxrpc_fast_process_packet(call, skb);
rxrpc_put_call(call); rxrpc_put_call(call, rxrpc_call_put);
goto done; goto done;
resend_final_ack: resend_final_ack:
_debug("final ack again"); _debug("final ack again");
rxrpc_get_call(call); rxrpc_get_call(call, rxrpc_call_got);
set_bit(RXRPC_CALL_EV_ACK_FINAL, &call->events); set_bit(RXRPC_CALL_EV_ACK_FINAL, &call->events);
rxrpc_queue_call(call); rxrpc_queue_call(call);
goto free_unlock; goto free_unlock;

View File

@ -79,7 +79,8 @@ int rxrpc_recvmsg(struct socket *sock, struct msghdr *msg, size_t len,
if (rx->sk.sk_state != RXRPC_SERVER_LISTENING) { if (rx->sk.sk_state != RXRPC_SERVER_LISTENING) {
release_sock(&rx->sk); release_sock(&rx->sk);
if (continue_call) if (continue_call)
rxrpc_put_call(continue_call); rxrpc_put_call(continue_call,
rxrpc_call_put);
return -ENODATA; return -ENODATA;
} }
} }
@ -137,13 +138,13 @@ int rxrpc_recvmsg(struct socket *sock, struct msghdr *msg, size_t len,
if (call != continue_call || if (call != continue_call ||
skb->mark != RXRPC_SKB_MARK_DATA) { skb->mark != RXRPC_SKB_MARK_DATA) {
release_sock(&rx->sk); release_sock(&rx->sk);
rxrpc_put_call(continue_call); rxrpc_put_call(continue_call, rxrpc_call_put);
_leave(" = %d [noncont]", copied); _leave(" = %d [noncont]", copied);
return copied; return copied;
} }
} }
rxrpc_get_call(call); rxrpc_get_call(call, rxrpc_call_got);
/* copy the peer address and timestamp */ /* copy the peer address and timestamp */
if (!continue_call) { if (!continue_call) {
@ -233,7 +234,7 @@ int rxrpc_recvmsg(struct socket *sock, struct msghdr *msg, size_t len,
if (!continue_call) if (!continue_call)
continue_call = sp->call; continue_call = sp->call;
else else
rxrpc_put_call(call); rxrpc_put_call(call, rxrpc_call_put);
call = NULL; call = NULL;
if (flags & MSG_PEEK) { if (flags & MSG_PEEK) {
@ -255,9 +256,9 @@ int rxrpc_recvmsg(struct socket *sock, struct msghdr *msg, size_t len,
out: out:
release_sock(&rx->sk); release_sock(&rx->sk);
if (call) if (call)
rxrpc_put_call(call); rxrpc_put_call(call, rxrpc_call_put);
if (continue_call) if (continue_call)
rxrpc_put_call(continue_call); rxrpc_put_call(continue_call, rxrpc_call_put);
_leave(" = %d [data]", copied); _leave(" = %d [data]", copied);
return copied; return copied;
@ -341,18 +342,18 @@ terminal_message:
} }
release_sock(&rx->sk); release_sock(&rx->sk);
rxrpc_put_call(call); rxrpc_put_call(call, rxrpc_call_put);
if (continue_call) if (continue_call)
rxrpc_put_call(continue_call); rxrpc_put_call(continue_call, rxrpc_call_put);
_leave(" = %d", ret); _leave(" = %d", ret);
return ret; return ret;
copy_error: copy_error:
_debug("copy error"); _debug("copy error");
release_sock(&rx->sk); release_sock(&rx->sk);
rxrpc_put_call(call); rxrpc_put_call(call, rxrpc_call_put);
if (continue_call) if (continue_call)
rxrpc_put_call(continue_call); rxrpc_put_call(continue_call, rxrpc_call_put);
_leave(" = %d", ret); _leave(" = %d", ret);
return ret; return ret;
@ -361,7 +362,7 @@ wait_interrupted:
wait_error: wait_error:
finish_wait(sk_sleep(&rx->sk), &wait); finish_wait(sk_sleep(&rx->sk), &wait);
if (continue_call) if (continue_call)
rxrpc_put_call(continue_call); rxrpc_put_call(continue_call, rxrpc_call_put);
if (copied) if (copied)
copied = ret; copied = ret;
_leave(" = %d [waitfail %d]", copied, ret); _leave(" = %d [waitfail %d]", copied, ret);

View File

@ -534,7 +534,7 @@ int rxrpc_do_sendmsg(struct rxrpc_sock *rx, struct msghdr *msg, size_t len)
call = rxrpc_accept_call(rx, user_call_ID, NULL); call = rxrpc_accept_call(rx, user_call_ID, NULL);
if (IS_ERR(call)) if (IS_ERR(call))
return PTR_ERR(call); return PTR_ERR(call);
rxrpc_put_call(call); rxrpc_put_call(call, rxrpc_call_put);
return 0; return 0;
} }
@ -573,7 +573,7 @@ int rxrpc_do_sendmsg(struct rxrpc_sock *rx, struct msghdr *msg, size_t len)
ret = rxrpc_send_data(rx, call, msg, len); ret = rxrpc_send_data(rx, call, msg, len);
} }
rxrpc_put_call(call); rxrpc_put_call(call, rxrpc_call_put);
_leave(" = %d", ret); _leave(" = %d", ret);
return ret; return ret;
} }

View File

@ -35,7 +35,7 @@ static void rxrpc_request_final_ACK(struct rxrpc_call *call)
/* get an extra ref on the call for the final-ACK generator to /* get an extra ref on the call for the final-ACK generator to
* release */ * release */
rxrpc_get_call(call); rxrpc_get_call(call, rxrpc_call_got);
set_bit(RXRPC_CALL_EV_ACK_FINAL, &call->events); set_bit(RXRPC_CALL_EV_ACK_FINAL, &call->events);
if (try_to_del_timer_sync(&call->ack_timer) >= 0) if (try_to_del_timer_sync(&call->ack_timer) >= 0)
rxrpc_queue_call(call); rxrpc_queue_call(call);