From 5cf9dd55a0ec26428f2824aadd16bfa305a5b603 Mon Sep 17 00:00:00 2001 From: David Howells Date: Mon, 9 Apr 2018 21:12:31 +0100 Subject: afs: Prospectively look up extra files when doing a single lookup When afs_lookup() is called, prospectively look up the next 50 uncached fids also from that same directory and cache the results, rather than just looking up the one file requested. This allows us to use the FS.InlineBulkStatus RPC op to increase efficiency by fetching up to 50 file statuses at a time. Signed-off-by: David Howells --- include/trace/events/afs.h | 2 ++ 1 file changed, 2 insertions(+) (limited to 'include/trace') diff --git a/include/trace/events/afs.h b/include/trace/events/afs.h index 63815f6..0419b7e 100644 --- a/include/trace/events/afs.h +++ b/include/trace/events/afs.h @@ -49,6 +49,7 @@ enum afs_fs_operation { afs_FS_ExtendLock = 157, /* AFS Extend a file lock */ afs_FS_ReleaseLock = 158, /* AFS Release a file lock */ afs_FS_Lookup = 161, /* AFS lookup file in directory */ + afs_FS_InlineBulkStatus = 65536, /* AFS Fetch multiple file statuses with errors */ afs_FS_FetchData64 = 65537, /* AFS Fetch file data */ afs_FS_StoreData64 = 65538, /* AFS Store file data */ afs_FS_GiveUpAllCallBacks = 65539, /* AFS Give up all our callbacks on a server */ @@ -93,6 +94,7 @@ enum afs_vl_operation { EM(afs_FS_ExtendLock, "FS.ExtendLock") \ EM(afs_FS_ReleaseLock, "FS.ReleaseLock") \ EM(afs_FS_Lookup, "FS.Lookup") \ + EM(afs_FS_InlineBulkStatus, "FS.InlineBulkStatus") \ EM(afs_FS_FetchData64, "FS.FetchData64") \ EM(afs_FS_StoreData64, "FS.StoreData64") \ EM(afs_FS_GiveUpAllCallBacks, "FS.GiveUpAllCallBacks") \ -- cgit v1.1 From 63a4681ff39cb63314b8ff41319e70fb0e606ed2 Mon Sep 17 00:00:00 2001 From: David Howells Date: Fri, 6 Apr 2018 14:17:25 +0100 Subject: afs: Locally edit directory data for mkdir/create/unlink/... Locally edit the contents of an AFS directory upon a successful inode operation that modifies that directory (such as mkdir, create and unlink) so that we can avoid the current practice of re-downloading the directory after each change. This is viable provided that the directory version number we get back from the modifying RPC op is exactly incremented by 1 from what we had previously. The data in the directory contents is in a defined format that we have to parse locally to perform lookups and readdir, so modifying isn't a problem. If the edit fails, we just clear the VALID flag on the directory and it will be reloaded next time it is needed. Signed-off-by: David Howells --- include/trace/events/afs.h | 90 ++++++++++++++++++++++++++++++++++++++++++++++ 1 file changed, 90 insertions(+) (limited to 'include/trace') diff --git a/include/trace/events/afs.h b/include/trace/events/afs.h index 0419b7e..f46dee0 100644 --- a/include/trace/events/afs.h +++ b/include/trace/events/afs.h @@ -63,6 +63,27 @@ enum afs_vl_operation { afs_VL_GetCapabilities = 65537, /* AFS Get VL server capabilities */ }; +enum afs_edit_dir_op { + afs_edit_dir_create, + afs_edit_dir_create_error, + afs_edit_dir_create_inval, + afs_edit_dir_create_nospc, + afs_edit_dir_delete, + afs_edit_dir_delete_error, + afs_edit_dir_delete_inval, + afs_edit_dir_delete_noent, +}; + +enum afs_edit_dir_reason { + afs_edit_dir_for_create, + afs_edit_dir_for_link, + afs_edit_dir_for_mkdir, + afs_edit_dir_for_rename, + afs_edit_dir_for_rmdir, + afs_edit_dir_for_symlink, + afs_edit_dir_for_unlink, +}; + #endif /* end __AFS_DECLARE_TRACE_ENUMS_ONCE_ONLY */ /* @@ -106,6 +127,25 @@ enum afs_vl_operation { EM(afs_YFSVL_GetEndpoints, "YFSVL.GetEndpoints") \ E_(afs_VL_GetCapabilities, "VL.GetCapabilities") +#define afs_edit_dir_ops \ + EM(afs_edit_dir_create, "create") \ + EM(afs_edit_dir_create_error, "c_fail") \ + EM(afs_edit_dir_create_inval, "c_invl") \ + EM(afs_edit_dir_create_nospc, "c_nspc") \ + EM(afs_edit_dir_delete, "delete") \ + EM(afs_edit_dir_delete_error, "d_err ") \ + EM(afs_edit_dir_delete_inval, "d_invl") \ + E_(afs_edit_dir_delete_noent, "d_nent") + +#define afs_edit_dir_reasons \ + EM(afs_edit_dir_for_create, "Create") \ + EM(afs_edit_dir_for_link, "Link ") \ + EM(afs_edit_dir_for_mkdir, "MkDir ") \ + EM(afs_edit_dir_for_rename, "Rename") \ + EM(afs_edit_dir_for_rmdir, "RmDir ") \ + EM(afs_edit_dir_for_symlink, "Symlnk") \ + E_(afs_edit_dir_for_unlink, "Unlink") + /* * Export enum symbols via userspace. @@ -118,6 +158,8 @@ enum afs_vl_operation { afs_call_traces; afs_fs_operations; afs_vl_operations; +afs_edit_dir_ops; +afs_edit_dir_reasons; /* * Now redefine the EM() and E_() macros to map the enums to the strings that @@ -464,6 +506,54 @@ TRACE_EVENT(afs_call_state, __entry->ret, __entry->abort) ); +TRACE_EVENT(afs_edit_dir, + TP_PROTO(struct afs_vnode *dvnode, + enum afs_edit_dir_reason why, + enum afs_edit_dir_op op, + unsigned int block, + unsigned int slot, + unsigned int f_vnode, + unsigned int f_unique, + const char *name), + + TP_ARGS(dvnode, why, op, block, slot, f_vnode, f_unique, name), + + TP_STRUCT__entry( + __field(unsigned int, vnode ) + __field(unsigned int, unique ) + __field(enum afs_edit_dir_reason, why ) + __field(enum afs_edit_dir_op, op ) + __field(unsigned int, block ) + __field(unsigned short, slot ) + __field(unsigned int, f_vnode ) + __field(unsigned int, f_unique ) + __array(char, name, 18 ) + ), + + TP_fast_assign( + int __len = strlen(name); + __len = min(__len, 17); + __entry->vnode = dvnode->fid.vnode; + __entry->unique = dvnode->fid.unique; + __entry->why = why; + __entry->op = op; + __entry->block = block; + __entry->slot = slot; + __entry->f_vnode = f_vnode; + __entry->f_unique = f_unique; + memcpy(__entry->name, name, __len); + __entry->name[__len] = 0; + ), + + TP_printk("d=%x:%x %s %s %u[%u] f=%x:%x %s", + __entry->vnode, __entry->unique, + __print_symbolic(__entry->why, afs_edit_dir_reasons), + __print_symbolic(__entry->op, afs_edit_dir_ops), + __entry->block, __entry->slot, + __entry->f_vnode, __entry->f_unique, + __entry->name) + ); + #endif /* _TRACE_AFS_H */ /* This part must be outside protection */ -- cgit v1.1 From 5f702c8e124f967146a735a19f0b00a2469487d1 Mon Sep 17 00:00:00 2001 From: David Howells Date: Fri, 6 Apr 2018 14:17:25 +0100 Subject: afs: Trace protocol errors Trace protocol errors detected in afs. Signed-off-by: David Howells --- include/trace/events/afs.h | 21 +++++++++++++++++++++ 1 file changed, 21 insertions(+) (limited to 'include/trace') diff --git a/include/trace/events/afs.h b/include/trace/events/afs.h index f46dee0..f0820554 100644 --- a/include/trace/events/afs.h +++ b/include/trace/events/afs.h @@ -554,6 +554,27 @@ TRACE_EVENT(afs_edit_dir, __entry->name) ); +TRACE_EVENT(afs_protocol_error, + TP_PROTO(struct afs_call *call, int error, const void *where), + + TP_ARGS(call, error, where), + + TP_STRUCT__entry( + __field(unsigned int, call ) + __field(int, error ) + __field(const void *, where ) + ), + + TP_fast_assign( + __entry->call = call ? call->debug_id : 0; + __entry->error = error; + __entry->where = where; + ), + + TP_printk("c=%08x r=%d sp=%pSR", + __entry->call, __entry->error, __entry->where) + ); + #endif /* _TRACE_AFS_H */ /* This part must be outside protection */ -- cgit v1.1 From e671edb9428c8a61662aaf8c39f5edced7cc45c7 Mon Sep 17 00:00:00 2001 From: Chuck Lever Date: Fri, 16 Mar 2018 10:33:44 -0400 Subject: sunrpc: Simplify synopsis of some trace points Clean up: struct rpc_task carries a pointer to a struct rpc_clnt, and in fact task->tk_client is always what is passed into trace points that are already passing @task. Signed-off-by: Chuck Lever Signed-off-by: Anna Schumaker --- include/trace/events/sunrpc.h | 40 +++++++++++++++++++++------------------- 1 file changed, 21 insertions(+), 19 deletions(-) (limited to 'include/trace') diff --git a/include/trace/events/sunrpc.h b/include/trace/events/sunrpc.h index 970c91a..53bbaea 100644 --- a/include/trace/events/sunrpc.h +++ b/include/trace/events/sunrpc.h @@ -50,9 +50,9 @@ DEFINE_EVENT(rpc_task_status, rpc_bind_status, ); TRACE_EVENT(rpc_connect_status, - TP_PROTO(struct rpc_task *task, int status), + TP_PROTO(const struct rpc_task *task), - TP_ARGS(task, status), + TP_ARGS(task), TP_STRUCT__entry( __field(unsigned int, task_id) @@ -63,7 +63,7 @@ TRACE_EVENT(rpc_connect_status, TP_fast_assign( __entry->task_id = task->tk_pid; __entry->client_id = task->tk_client->cl_clid; - __entry->status = status; + __entry->status = task->tk_status; ), TP_printk("task:%u@%u status=%d", @@ -103,9 +103,9 @@ TRACE_EVENT(rpc_request, DECLARE_EVENT_CLASS(rpc_task_running, - TP_PROTO(const struct rpc_clnt *clnt, const struct rpc_task *task, const void *action), + TP_PROTO(const struct rpc_task *task, const void *action), - TP_ARGS(clnt, task, action), + TP_ARGS(task, action), TP_STRUCT__entry( __field(unsigned int, task_id) @@ -117,7 +117,8 @@ DECLARE_EVENT_CLASS(rpc_task_running, ), TP_fast_assign( - __entry->client_id = clnt ? clnt->cl_clid : -1; + __entry->client_id = task->tk_client ? + task->tk_client->cl_clid : -1; __entry->task_id = task->tk_pid; __entry->action = action; __entry->runstate = task->tk_runstate; @@ -136,33 +137,33 @@ DECLARE_EVENT_CLASS(rpc_task_running, DEFINE_EVENT(rpc_task_running, rpc_task_begin, - TP_PROTO(const struct rpc_clnt *clnt, const struct rpc_task *task, const void *action), + TP_PROTO(const struct rpc_task *task, const void *action), - TP_ARGS(clnt, task, action) + TP_ARGS(task, action) ); DEFINE_EVENT(rpc_task_running, rpc_task_run_action, - TP_PROTO(const struct rpc_clnt *clnt, const struct rpc_task *task, const void *action), + TP_PROTO(const struct rpc_task *task, const void *action), - TP_ARGS(clnt, task, action) + TP_ARGS(task, action) ); DEFINE_EVENT(rpc_task_running, rpc_task_complete, - TP_PROTO(const struct rpc_clnt *clnt, const struct rpc_task *task, const void *action), + TP_PROTO(const struct rpc_task *task, const void *action), - TP_ARGS(clnt, task, action) + TP_ARGS(task, action) ); DECLARE_EVENT_CLASS(rpc_task_queued, - TP_PROTO(const struct rpc_clnt *clnt, const struct rpc_task *task, const struct rpc_wait_queue *q), + TP_PROTO(const struct rpc_task *task, const struct rpc_wait_queue *q), - TP_ARGS(clnt, task, q), + TP_ARGS(task, q), TP_STRUCT__entry( __field(unsigned int, task_id) @@ -175,7 +176,8 @@ DECLARE_EVENT_CLASS(rpc_task_queued, ), TP_fast_assign( - __entry->client_id = clnt ? clnt->cl_clid : -1; + __entry->client_id = task->tk_client ? + task->tk_client->cl_clid : -1; __entry->task_id = task->tk_pid; __entry->timeout = task->tk_timeout; __entry->runstate = task->tk_runstate; @@ -196,17 +198,17 @@ DECLARE_EVENT_CLASS(rpc_task_queued, DEFINE_EVENT(rpc_task_queued, rpc_task_sleep, - TP_PROTO(const struct rpc_clnt *clnt, const struct rpc_task *task, const struct rpc_wait_queue *q), + TP_PROTO(const struct rpc_task *task, const struct rpc_wait_queue *q), - TP_ARGS(clnt, task, q) + TP_ARGS(task, q) ); DEFINE_EVENT(rpc_task_queued, rpc_task_wakeup, - TP_PROTO(const struct rpc_clnt *clnt, const struct rpc_task *task, const struct rpc_wait_queue *q), + TP_PROTO(const struct rpc_task *task, const struct rpc_wait_queue *q), - TP_ARGS(clnt, task, q) + TP_ARGS(task, q) ); -- cgit v1.1 From 40bf7eb304b5659991ed932c0cd5bee6a7c88f4f Mon Sep 17 00:00:00 2001 From: Chuck Lever Date: Fri, 16 Mar 2018 10:33:49 -0400 Subject: sunrpc: Add static trace point to report RPC latency stats Introduce a low-overhead mechanism to report information about latencies of individual RPCs. The goal is to enable user space to filter the trace record for latency outliers, or build histograms, etc. Signed-off-by: Chuck Lever Signed-off-by: Anna Schumaker --- include/trace/events/sunrpc.h | 45 +++++++++++++++++++++++++++++++++++++++++++ 1 file changed, 45 insertions(+) (limited to 'include/trace') diff --git a/include/trace/events/sunrpc.h b/include/trace/events/sunrpc.h index 53bbaea..fda9e72 100644 --- a/include/trace/events/sunrpc.h +++ b/include/trace/events/sunrpc.h @@ -212,6 +212,51 @@ DEFINE_EVENT(rpc_task_queued, rpc_task_wakeup, ); +TRACE_EVENT(rpc_stats_latency, + + TP_PROTO( + const struct rpc_task *task, + ktime_t backlog, + ktime_t rtt, + ktime_t execute + ), + + TP_ARGS(task, backlog, rtt, execute), + + TP_STRUCT__entry( + __field(u32, xid) + __field(int, version) + __string(progname, task->tk_client->cl_program->name) + __string(procname, rpc_proc_name(task)) + __field(unsigned long, backlog) + __field(unsigned long, rtt) + __field(unsigned long, execute) + __string(addr, + task->tk_xprt->address_strings[RPC_DISPLAY_ADDR]) + __string(port, + task->tk_xprt->address_strings[RPC_DISPLAY_PORT]) + ), + + TP_fast_assign( + __entry->xid = be32_to_cpu(task->tk_rqstp->rq_xid); + __entry->version = task->tk_client->cl_vers; + __assign_str(progname, task->tk_client->cl_program->name) + __assign_str(procname, rpc_proc_name(task)) + __entry->backlog = ktime_to_us(backlog); + __entry->rtt = ktime_to_us(rtt); + __entry->execute = ktime_to_us(execute); + __assign_str(addr, + task->tk_xprt->address_strings[RPC_DISPLAY_ADDR]); + __assign_str(port, + task->tk_xprt->address_strings[RPC_DISPLAY_PORT]); + ), + + TP_printk("peer=[%s]:%s xid=0x%08x %sv%d %s backlog=%lu rtt=%lu execute=%lu", + __get_str(addr), __get_str(port), __entry->xid, + __get_str(progname), __entry->version, __get_str(procname), + __entry->backlog, __entry->rtt, __entry->execute) +); + /* * First define the enums in the below macros to be exported to userspace * via TRACE_DEFINE_ENUM(). -- cgit v1.1 From a25a4cb3af177a4cf5621ffbf4fa89ae60c6d4d7 Mon Sep 17 00:00:00 2001 From: Chuck Lever Date: Fri, 16 Mar 2018 10:33:55 -0400 Subject: sunrpc: Add static trace point to report result of RPC ping This information can help track down local misconfiguration issues as well as network partitions and unresponsive servers. There are several ways to send a ping, and with transport multi- plexing, the exact rpc_xprt that is used is sometimes not known by the upper layer. The rpc_xprt pointer passed to the trace point call also has to be RCU-safe. I found a spot inside the client FSM where an rpc_xprt pointer is always available and safe to use. Suggested-by: Bill Baker Signed-off-by: Chuck Lever Signed-off-by: Anna Schumaker --- include/trace/events/sunrpc.h | 21 +++++++++++++++++++++ 1 file changed, 21 insertions(+) (limited to 'include/trace') diff --git a/include/trace/events/sunrpc.h b/include/trace/events/sunrpc.h index fda9e72..76887d6 100644 --- a/include/trace/events/sunrpc.h +++ b/include/trace/events/sunrpc.h @@ -453,6 +453,27 @@ DEFINE_EVENT(rpc_xprt_event, xprt_complete_rqst, TP_PROTO(struct rpc_xprt *xprt, __be32 xid, int status), TP_ARGS(xprt, xid, status)); +TRACE_EVENT(xprt_ping, + TP_PROTO(const struct rpc_xprt *xprt, int status), + + TP_ARGS(xprt, status), + + TP_STRUCT__entry( + __field(int, status) + __string(addr, xprt->address_strings[RPC_DISPLAY_ADDR]) + __string(port, xprt->address_strings[RPC_DISPLAY_PORT]) + ), + + TP_fast_assign( + __entry->status = status; + __assign_str(addr, xprt->address_strings[RPC_DISPLAY_ADDR]); + __assign_str(port, xprt->address_strings[RPC_DISPLAY_PORT]); + ), + + TP_printk("peer=[%s]:%s status=%d", + __get_str(addr), __get_str(port), __entry->status) +); + TRACE_EVENT(xs_tcp_data_ready, TP_PROTO(struct rpc_xprt *xprt, int err, unsigned int total), -- cgit v1.1