From 051d25250b55c215a2254a0130d46fbd38bcbcc0 Mon Sep 17 00:00:00 2001 From: David Howells Date: Thu, 20 Jun 2019 18:12:16 +0100 Subject: afs: Add some callback management tracepoints Add a couple of tracepoints to track callback management: (1) afs_cb_miss - Logs when we were unable to apply a callback, either due to the inode being discarded or due to a competing thread applying a callback first. (2) afs_cb_break - Logs when we attempted to clear the noted callback promise, either due to the server explicitly breaking the callback, the callback promise lapsing or a local event obsoleting it. Signed-off-by: David Howells --- include/trace/events/afs.h | 69 ++++++++++++++++++++++++++++++++++++++++++++++ 1 file changed, 69 insertions(+) (limited to 'include/trace') diff --git a/include/trace/events/afs.h b/include/trace/events/afs.h index 562f854ac4bf..34628e207849 100644 --- a/include/trace/events/afs.h +++ b/include/trace/events/afs.h @@ -195,6 +195,17 @@ enum afs_flock_operation { afs_flock_op_wake, }; +enum afs_cb_break_reason { + afs_cb_break_no_break, + afs_cb_break_for_callback, + afs_cb_break_for_deleted, + afs_cb_break_for_lapsed, + afs_cb_break_for_unlink, + afs_cb_break_for_vsbreak, + afs_cb_break_for_volume_callback, + afs_cb_break_for_zap, +}; + #endif /* end __AFS_DECLARE_TRACE_ENUMS_ONCE_ONLY */ /* @@ -374,6 +385,16 @@ enum afs_flock_operation { EM(afs_flock_op_unlock, "UNLOCK ") \ E_(afs_flock_op_wake, "WAKE ") +#define afs_cb_break_reasons \ + EM(afs_cb_break_no_break, "no-break") \ + EM(afs_cb_break_for_callback, "break-cb") \ + EM(afs_cb_break_for_deleted, "break-del") \ + EM(afs_cb_break_for_lapsed, "break-lapsed") \ + EM(afs_cb_break_for_unlink, "break-unlink") \ + EM(afs_cb_break_for_vsbreak, "break-vs") \ + EM(afs_cb_break_for_volume_callback, "break-v-cb") \ + E_(afs_cb_break_for_zap, "break-zap") + /* * Export enum symbols via userspace. */ @@ -392,6 +413,7 @@ afs_io_errors; afs_file_errors; afs_flock_types; afs_flock_operations; +afs_cb_break_reasons; /* * Now redefine the EM() and E_() macros to map the enums to the strings that @@ -1171,6 +1193,53 @@ TRACE_EVENT(afs_get_tree, __entry->cell, __entry->volume, __entry->vid) ); +TRACE_EVENT(afs_cb_break, + TP_PROTO(struct afs_fid *fid, unsigned int cb_break, + enum afs_cb_break_reason reason, bool skipped), + + TP_ARGS(fid, cb_break, reason, skipped), + + TP_STRUCT__entry( + __field_struct(struct afs_fid, fid ) + __field(unsigned int, cb_break ) + __field(enum afs_cb_break_reason, reason ) + __field(bool, skipped ) + ), + + TP_fast_assign( + __entry->fid = *fid; + __entry->cb_break = cb_break; + __entry->reason = reason; + __entry->skipped = skipped; + ), + + TP_printk("%llx:%llx:%x b=%x s=%u %s", + __entry->fid.vid, __entry->fid.vnode, __entry->fid.unique, + __entry->cb_break, + __entry->skipped, + __print_symbolic(__entry->reason, afs_cb_break_reasons)) + ); + +TRACE_EVENT(afs_cb_miss, + TP_PROTO(struct afs_fid *fid, enum afs_cb_break_reason reason), + + TP_ARGS(fid, reason), + + TP_STRUCT__entry( + __field_struct(struct afs_fid, fid ) + __field(enum afs_cb_break_reason, reason ) + ), + + TP_fast_assign( + __entry->fid = *fid; + __entry->reason = reason; + ), + + TP_printk(" %llx:%llx:%x %s", + __entry->fid.vid, __entry->fid.vnode, __entry->fid.unique, + __print_symbolic(__entry->reason, afs_cb_break_reasons)) + ); + #endif /* _TRACE_AFS_H */ /* This part must be outside protection */ -- cgit v1.2.3-55-g7522 From 452181936931f0f08923aba5e04e1e9ef58c389f Mon Sep 17 00:00:00 2001 From: David Howells Date: Thu, 20 Jun 2019 18:12:17 +0100 Subject: afs: Trace afs_server usage Add a tracepoint (afs_server) to track the afs_server object usage count. Signed-off-by: David Howells --- fs/afs/callback.c | 4 +-- fs/afs/cmservice.c | 5 +++- fs/afs/fsclient.c | 2 +- fs/afs/internal.h | 10 +++----- fs/afs/rxrpc.c | 2 +- fs/afs/server.c | 39 ++++++++++++++++++++++------ fs/afs/server_list.c | 6 +++-- include/trace/events/afs.h | 63 ++++++++++++++++++++++++++++++++++++++++++++++ 8 files changed, 110 insertions(+), 21 deletions(-) (limited to 'include/trace') diff --git a/fs/afs/callback.c b/fs/afs/callback.c index d66cd0364243..6cdd7047c809 100644 --- a/fs/afs/callback.c +++ b/fs/afs/callback.c @@ -48,7 +48,7 @@ static struct afs_cb_interest *afs_create_interest(struct afs_server *server, refcount_set(&new->usage, 1); new->sb = vnode->vfs_inode.i_sb; new->vid = vnode->volume->vid; - new->server = afs_get_server(server); + new->server = afs_get_server(server, afs_server_trace_get_new_cbi); INIT_HLIST_NODE(&new->cb_vlink); write_lock(&server->cb_break_lock); @@ -195,7 +195,7 @@ void afs_put_cb_interest(struct afs_net *net, struct afs_cb_interest *cbi) write_unlock(&cbi->server->cb_break_lock); if (vi) kfree_rcu(vi, rcu); - afs_put_server(net, cbi->server); + afs_put_server(net, cbi->server, afs_server_trace_put_cbi); } kfree_rcu(cbi, rcu); } diff --git a/fs/afs/cmservice.c b/fs/afs/cmservice.c index 01437cfe5432..e114d6be0c2b 100644 --- a/fs/afs/cmservice.c +++ b/fs/afs/cmservice.c @@ -260,8 +260,11 @@ static void SRXAFSCB_CallBack(struct work_struct *work) * server holds up change visibility till it receives our reply so as * to maintain cache coherency. */ - if (call->server) + if (call->server) { + trace_afs_server(call->server, atomic_read(&call->server->usage), + afs_server_trace_callback); afs_break_callbacks(call->server, call->count, call->request); + } afs_send_empty_reply(call); afs_put_call(call); diff --git a/fs/afs/fsclient.c b/fs/afs/fsclient.c index 48298408d6ac..8274e2e4a221 100644 --- a/fs/afs/fsclient.c +++ b/fs/afs/fsclient.c @@ -1915,7 +1915,7 @@ struct afs_call *afs_fs_get_capabilities(struct afs_net *net, return ERR_PTR(-ENOMEM); call->key = key; - call->server = afs_get_server(server); + call->server = afs_get_server(server, afs_server_trace_get_caps); call->server_index = server_index; call->upgrade = true; call->async = true; diff --git a/fs/afs/internal.h b/fs/afs/internal.h index 4d9b3e9a422a..b03f32137a20 100644 --- a/fs/afs/internal.h +++ b/fs/afs/internal.h @@ -518,6 +518,7 @@ struct afs_server { atomic_t usage; u32 addr_version; /* Address list version */ u32 cm_epoch; /* Server RxRPC epoch */ + unsigned int debug_id; /* Debugging ID for traces */ /* file service access */ rwlock_t fs_lock; /* access lock */ @@ -1244,17 +1245,12 @@ extern void __exit afs_clean_up_permit_cache(void); */ extern spinlock_t afs_server_peer_lock; -static inline struct afs_server *afs_get_server(struct afs_server *server) -{ - atomic_inc(&server->usage); - return server; -} - extern struct afs_server *afs_find_server(struct afs_net *, const struct sockaddr_rxrpc *); extern struct afs_server *afs_find_server_by_uuid(struct afs_net *, const uuid_t *); extern struct afs_server *afs_lookup_server(struct afs_cell *, struct key *, const uuid_t *); -extern void afs_put_server(struct afs_net *, struct afs_server *); +extern struct afs_server *afs_get_server(struct afs_server *, enum afs_server_trace); +extern void afs_put_server(struct afs_net *, struct afs_server *, enum afs_server_trace); extern void afs_manage_servers(struct work_struct *); extern void afs_servers_timer(struct timer_list *); extern void __net_exit afs_purge_servers(struct afs_net *); diff --git a/fs/afs/rxrpc.c b/fs/afs/rxrpc.c index 4fa5ce92b9b9..32d1721f41db 100644 --- a/fs/afs/rxrpc.c +++ b/fs/afs/rxrpc.c @@ -188,7 +188,7 @@ void afs_put_call(struct afs_call *call) if (call->type->destructor) call->type->destructor(call); - afs_put_server(call->net, call->server); + afs_put_server(call->net, call->server, afs_server_trace_put_call); afs_put_cb_interest(call->net, call->cbi); afs_put_addrlist(call->alist); kfree(call->request); diff --git a/fs/afs/server.c b/fs/afs/server.c index 52c170b59cfd..b69571bb9d37 100644 --- a/fs/afs/server.c +++ b/fs/afs/server.c @@ -17,6 +17,7 @@ static unsigned afs_server_gc_delay = 10; /* Server record timeout in seconds */ static unsigned afs_server_update_delay = 30; /* Time till VLDB recheck in secs */ +static atomic_t afs_server_debug_id; static void afs_inc_servers_outstanding(struct afs_net *net) { @@ -51,7 +52,7 @@ struct afs_server *afs_find_server(struct afs_net *net, do { if (server) - afs_put_server(net, server); + afs_put_server(net, server, afs_server_trace_put_find_rsq); server = NULL; read_seqbegin_or_lock(&net->fs_addr_lock, &seq); @@ -116,7 +117,7 @@ struct afs_server *afs_find_server_by_uuid(struct afs_net *net, const uuid_t *uu * changes. */ if (server) - afs_put_server(net, server); + afs_put_server(net, server, afs_server_trace_put_uuid_rsq); server = NULL; read_seqbegin_or_lock(&net->fs_lock, &seq); @@ -131,7 +132,7 @@ struct afs_server *afs_find_server_by_uuid(struct afs_net *net, const uuid_t *uu } else if (diff > 0) { p = p->rb_right; } else { - afs_get_server(server); + afs_get_server(server, afs_server_trace_get_by_uuid); break; } @@ -202,7 +203,7 @@ static struct afs_server *afs_install_server(struct afs_net *net, ret = 0; exists: - afs_get_server(server); + afs_get_server(server, afs_server_trace_get_install); write_sequnlock(&net->fs_lock); return server; } @@ -223,6 +224,7 @@ static struct afs_server *afs_alloc_server(struct afs_net *net, goto enomem; atomic_set(&server->usage, 1); + server->debug_id = atomic_inc_return(&afs_server_debug_id); RCU_INIT_POINTER(server->addresses, alist); server->addr_version = alist->version; server->uuid = *uuid; @@ -234,6 +236,7 @@ static struct afs_server *afs_alloc_server(struct afs_net *net, spin_lock_init(&server->probe_lock); afs_inc_servers_outstanding(net); + trace_afs_server(server, 1, afs_server_trace_alloc); _leave(" = %p", server); return server; @@ -328,10 +331,23 @@ void afs_servers_timer(struct timer_list *timer) afs_dec_servers_outstanding(net); } +/* + * Get a reference on a server object. + */ +struct afs_server *afs_get_server(struct afs_server *server, + enum afs_server_trace reason) +{ + unsigned int u = atomic_inc_return(&server->usage); + + trace_afs_server(server, u, reason); + return server; +} + /* * Release a reference on a server record. */ -void afs_put_server(struct afs_net *net, struct afs_server *server) +void afs_put_server(struct afs_net *net, struct afs_server *server, + enum afs_server_trace reason) { unsigned int usage; @@ -342,7 +358,7 @@ void afs_put_server(struct afs_net *net, struct afs_server *server) usage = atomic_dec_return(&server->usage); - _enter("{%u}", usage); + trace_afs_server(server, usage, reason); if (likely(usage > 0)) return; @@ -354,6 +370,8 @@ static void afs_server_rcu(struct rcu_head *rcu) { struct afs_server *server = container_of(rcu, struct afs_server, rcu); + trace_afs_server(server, atomic_read(&server->usage), + afs_server_trace_free); afs_put_addrlist(rcu_access_pointer(server->addresses)); kfree(server); } @@ -369,7 +387,9 @@ static void afs_destroy_server(struct afs_net *net, struct afs_server *server) .index = alist->preferred, .error = 0, }; - _enter("%p", server); + + trace_afs_server(server, atomic_read(&server->usage), + afs_server_trace_give_up_cb); if (test_bit(AFS_SERVER_FL_MAY_HAVE_CB, &server->flags)) afs_fs_give_up_all_callbacks(net, server, &ac, NULL); @@ -377,6 +397,8 @@ static void afs_destroy_server(struct afs_net *net, struct afs_server *server) wait_var_event(&server->probe_outstanding, atomic_read(&server->probe_outstanding) == 0); + trace_afs_server(server, atomic_read(&server->usage), + afs_server_trace_destroy); call_rcu(&server->rcu, afs_server_rcu); afs_dec_servers_outstanding(net); } @@ -396,6 +418,7 @@ static void afs_gc_servers(struct afs_net *net, struct afs_server *gc_list) write_seqlock(&net->fs_lock); usage = 1; deleted = atomic_try_cmpxchg(&server->usage, &usage, 0); + trace_afs_server(server, usage, afs_server_trace_gc); if (deleted) { rb_erase(&server->uuid_rb, &net->fs_servers); hlist_del_rcu(&server->proc_link); @@ -518,6 +541,8 @@ static noinline bool afs_update_server_record(struct afs_fs_cursor *fc, struct a _enter(""); + trace_afs_server(server, atomic_read(&server->usage), afs_server_trace_update); + alist = afs_vl_lookup_addrs(fc->vnode->volume->cell, fc->key, &server->uuid); if (IS_ERR(alist)) { diff --git a/fs/afs/server_list.c b/fs/afs/server_list.c index 155dc14caef9..f5c78607366e 100644 --- a/fs/afs/server_list.c +++ b/fs/afs/server_list.c @@ -20,7 +20,8 @@ void afs_put_serverlist(struct afs_net *net, struct afs_server_list *slist) if (slist && refcount_dec_and_test(&slist->usage)) { for (i = 0; i < slist->nr_servers; i++) { afs_put_cb_interest(net, slist->servers[i].cb_interest); - afs_put_server(net, slist->servers[i].server); + afs_put_server(net, slist->servers[i].server, + afs_server_trace_put_slist); } kfree(slist); } @@ -71,7 +72,8 @@ struct afs_server_list *afs_alloc_server_list(struct afs_cell *cell, break; if (j < slist->nr_servers) { if (slist->servers[j].server == server) { - afs_put_server(cell->net, server); + afs_put_server(cell->net, server, + afs_server_trace_put_slist_isort); continue; } diff --git a/include/trace/events/afs.h b/include/trace/events/afs.h index 34628e207849..29815dc021a4 100644 --- a/include/trace/events/afs.h +++ b/include/trace/events/afs.h @@ -31,6 +31,26 @@ enum afs_call_trace { afs_call_trace_work, }; +enum afs_server_trace { + afs_server_trace_alloc, + afs_server_trace_callback, + afs_server_trace_destroy, + afs_server_trace_free, + afs_server_trace_gc, + afs_server_trace_get_by_uuid, + afs_server_trace_get_caps, + afs_server_trace_get_install, + afs_server_trace_get_new_cbi, + afs_server_trace_give_up_cb, + afs_server_trace_put_call, + afs_server_trace_put_cbi, + afs_server_trace_put_find_rsq, + afs_server_trace_put_slist, + afs_server_trace_put_slist_isort, + afs_server_trace_put_uuid_rsq, + afs_server_trace_update, +}; + enum afs_fs_operation { afs_FS_FetchData = 130, /* AFS Fetch file data */ afs_FS_FetchACL = 131, /* AFS Fetch file ACL */ @@ -219,6 +239,25 @@ enum afs_cb_break_reason { EM(afs_call_trace_wake, "WAKE ") \ E_(afs_call_trace_work, "WORK ") +#define afs_server_traces \ + EM(afs_server_trace_alloc, "ALLOC ") \ + EM(afs_server_trace_callback, "CALLBACK ") \ + EM(afs_server_trace_destroy, "DESTROY ") \ + EM(afs_server_trace_free, "FREE ") \ + EM(afs_server_trace_gc, "GC ") \ + EM(afs_server_trace_get_by_uuid, "GET uuid ") \ + EM(afs_server_trace_get_caps, "GET caps ") \ + EM(afs_server_trace_get_install, "GET inst ") \ + EM(afs_server_trace_get_new_cbi, "GET cbi ") \ + EM(afs_server_trace_give_up_cb, "giveup-cb") \ + EM(afs_server_trace_put_call, "PUT call ") \ + EM(afs_server_trace_put_cbi, "PUT cbi ") \ + EM(afs_server_trace_put_find_rsq, "PUT f-rsq") \ + EM(afs_server_trace_put_slist, "PUT slist") \ + EM(afs_server_trace_put_slist_isort, "PUT isort") \ + EM(afs_server_trace_put_uuid_rsq, "PUT u-req") \ + E_(afs_server_trace_update, "UPDATE") + #define afs_fs_operations \ EM(afs_FS_FetchData, "FS.FetchData") \ EM(afs_FS_FetchStatus, "FS.FetchStatus") \ @@ -404,6 +443,7 @@ enum afs_cb_break_reason { #define E_(a, b) TRACE_DEFINE_ENUM(a); afs_call_traces; +afs_server_traces; afs_fs_operations; afs_vl_operations; afs_edit_dir_ops; @@ -1240,6 +1280,29 @@ TRACE_EVENT(afs_cb_miss, __print_symbolic(__entry->reason, afs_cb_break_reasons)) ); +TRACE_EVENT(afs_server, + TP_PROTO(struct afs_server *server, int usage, enum afs_server_trace reason), + + TP_ARGS(server, usage, reason), + + TP_STRUCT__entry( + __field(unsigned int, server ) + __field(int, usage ) + __field(int, reason ) + ), + + TP_fast_assign( + __entry->server = server->debug_id; + __entry->usage = usage; + __entry->reason = reason; + ), + + TP_printk("s=%08x %s u=%d", + __entry->server, + __print_symbolic(__entry->reason, afs_server_traces), + __entry->usage) + ); + #endif /* _TRACE_AFS_H */ /* This part must be outside protection */ -- cgit v1.2.3-55-g7522