From 03edb90f57a5f7edaa13db3174e269331ef9a527 Mon Sep 17 00:00:00 2001 From: Chuck Lever Date: Tue, 27 Mar 2018 10:49:53 -0400 Subject: sunrpc: Update show_svc_xprt_flags() to include recently added flags XPT_KILL_TEMP was added by commit 546125d16142 ("sunrpc: don't call sleeping functions from the notifier block callbacks"), and XPT_CONG_CTRL was added by commit 362142b25843 ("sunrpc: flag transports as having congestion control") . Signed-off-by: Chuck Lever Signed-off-by: J. Bruce Fields --- include/trace/events/sunrpc.h | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) (limited to 'include/trace') diff --git a/include/trace/events/sunrpc.h b/include/trace/events/sunrpc.h index 970c91a83173..a23144471b6b 100644 --- a/include/trace/events/sunrpc.h +++ b/include/trace/events/sunrpc.h @@ -591,7 +591,9 @@ DEFINE_EVENT(svc_rqst_status, svc_send, { (1UL << XPT_OLD), "XPT_OLD"}, \ { (1UL << XPT_LISTENER), "XPT_LISTENER"}, \ { (1UL << XPT_CACHE_AUTH), "XPT_CACHE_AUTH"}, \ - { (1UL << XPT_LOCAL), "XPT_LOCAL"}) + { (1UL << XPT_LOCAL), "XPT_LOCAL"}, \ + { (1UL << XPT_KILL_TEMP), "XPT_KILL_TEMP"}, \ + { (1UL << XPT_CONG_CTRL), "XPT_CONG_CTRL"}) TRACE_EVENT(svc_xprt_do_enqueue, TP_PROTO(struct svc_xprt *xprt, struct svc_rqst *rqst), -- cgit From caa3e106dc623eb41542e6221abecf9956e8a0e6 Mon Sep 17 00:00:00 2001 From: Chuck Lever Date: Tue, 27 Mar 2018 10:50:07 -0400 Subject: sunrpc: Move trace_svc_xprt_dequeue() Reduce the amount of noise generated by trace_svc_xprt_dequeue by moving it to the end of svc_get_next_xprt. This generates exactly one trace event when a ready xprt is found, rather than spurious events when there is no work to do. The empty events contain no information that can't be obtained simply by tracing function calls to svc_xprt_dequeue. A small additional benefit is simplification of the svc_xprt_event trace class, which no longer has to handle the case when the @xprt parameter is NULL. Signed-off-by: Chuck Lever Signed-off-by: J. Bruce Fields --- include/trace/events/sunrpc.h | 16 +++++----------- 1 file changed, 5 insertions(+), 11 deletions(-) (limited to 'include/trace') diff --git a/include/trace/events/sunrpc.h b/include/trace/events/sunrpc.h index a23144471b6b..9bba3070f873 100644 --- a/include/trace/events/sunrpc.h +++ b/include/trace/events/sunrpc.h @@ -634,24 +634,18 @@ DECLARE_EVENT_CLASS(svc_xprt_event, TP_STRUCT__entry( __field(struct svc_xprt *, xprt) __field(unsigned long, flags) - __dynamic_array(unsigned char, addr, xprt != NULL ? - xprt->xpt_remotelen : 0) + __dynamic_array(unsigned char, addr, xprt->xpt_remotelen) ), TP_fast_assign( __entry->xprt = xprt; - if (xprt) { - memcpy(__get_dynamic_array(addr), - &xprt->xpt_remote, - xprt->xpt_remotelen); - __entry->flags = xprt->xpt_flags; - } else - __entry->flags = 0; + __entry->flags = xprt->xpt_flags; + memcpy(__get_dynamic_array(addr), + &xprt->xpt_remote, xprt->xpt_remotelen); ), TP_printk("xprt=0x%p addr=%pIScp flags=%s", __entry->xprt, - __get_dynamic_array_len(addr) != 0 ? - (struct sockaddr *)__get_dynamic_array(addr) : NULL, + (struct sockaddr *)__get_dynamic_array(addr), show_svc_xprt_flags(__entry->flags)) ); -- cgit From 41f306d0c287e0cc04054135f9f4ceb003ad6795 Mon Sep 17 00:00:00 2001 From: Chuck Lever Date: Tue, 27 Mar 2018 10:50:42 -0400 Subject: sunrpc: Simplify trace_svc_recv There doesn't seem to be a lot of value in calling trace_svc_recv in the failing case. 1. There are two very common cases: one is the transport is not ready, and the other is shutdown. Neither is terribly interesting. 2. The trace record for the failing case contains nothing but the status code. Therefore the trace point call site in the error exit is removed. Since the trace point is now recording a length instead of a status, rename the status field and remove the case that records a zero XID. Signed-off-by: Chuck Lever Signed-off-by: J. Bruce Fields --- include/trace/events/sunrpc.h | 14 +++++++------- 1 file changed, 7 insertions(+), 7 deletions(-) (limited to 'include/trace') diff --git a/include/trace/events/sunrpc.h b/include/trace/events/sunrpc.h index 9bba3070f873..5849bfb3ece2 100644 --- a/include/trace/events/sunrpc.h +++ b/include/trace/events/sunrpc.h @@ -485,28 +485,28 @@ TRACE_EVENT(xs_tcp_data_recv, { (1UL << RQ_BUSY), "RQ_BUSY"}) TRACE_EVENT(svc_recv, - TP_PROTO(struct svc_rqst *rqst, int status), + TP_PROTO(struct svc_rqst *rqst, int len), - TP_ARGS(rqst, status), + TP_ARGS(rqst, len), TP_STRUCT__entry( __field(u32, xid) - __field(int, status) + __field(int, len) __field(unsigned long, flags) __dynamic_array(unsigned char, addr, rqst->rq_addrlen) ), TP_fast_assign( - __entry->xid = status > 0 ? be32_to_cpu(rqst->rq_xid) : 0; - __entry->status = status; + __entry->xid = be32_to_cpu(rqst->rq_xid); + __entry->len = len; __entry->flags = rqst->rq_flags; memcpy(__get_dynamic_array(addr), &rqst->rq_addr, rqst->rq_addrlen); ), - TP_printk("addr=%pIScp xid=0x%08x status=%d flags=%s", + TP_printk("addr=%pIScp xid=0x%08x len=%d flags=%s", (struct sockaddr *)__get_dynamic_array(addr), - __entry->xid, __entry->status, + __entry->xid, __entry->len, show_rqstp_flags(__entry->flags)) ); -- cgit From ece200ddd54b9ce840cfee554fb812560c545c7d Mon Sep 17 00:00:00 2001 From: Chuck Lever Date: Tue, 27 Mar 2018 10:51:00 -0400 Subject: sunrpc: Save remote presentation address in svc_xprt for trace events TP_printk defines a format string that is passed to user space for converting raw trace event records to something human-readable. My user space's printf (Oracle Linux 7), however, does not have a %pI format specifier. The result is that what is supposed to be an IP address in the output of "trace-cmd report" is just a string that says the field couldn't be displayed. To fix this, adopt the same approach as the client: maintain a pre- formated presentation address for occasions when %pI is not available. The location of the trace_svc_send trace point is adjusted so that rqst->rq_xprt is not NULL when the trace event is recorded. Signed-off-by: Chuck Lever Signed-off-by: J. Bruce Fields --- include/trace/events/sunrpc.h | 89 ++++++++++++++++--------------------------- 1 file changed, 33 insertions(+), 56 deletions(-) (limited to 'include/trace') diff --git a/include/trace/events/sunrpc.h b/include/trace/events/sunrpc.h index 5849bfb3ece2..1ec8c4c45766 100644 --- a/include/trace/events/sunrpc.h +++ b/include/trace/events/sunrpc.h @@ -493,20 +493,18 @@ TRACE_EVENT(svc_recv, __field(u32, xid) __field(int, len) __field(unsigned long, flags) - __dynamic_array(unsigned char, addr, rqst->rq_addrlen) + __string(addr, rqst->rq_xprt->xpt_remotebuf) ), TP_fast_assign( __entry->xid = be32_to_cpu(rqst->rq_xid); __entry->len = len; __entry->flags = rqst->rq_flags; - memcpy(__get_dynamic_array(addr), - &rqst->rq_addr, rqst->rq_addrlen); + __assign_str(addr, rqst->rq_xprt->xpt_remotebuf); ), - TP_printk("addr=%pIScp xid=0x%08x len=%d flags=%s", - (struct sockaddr *)__get_dynamic_array(addr), - __entry->xid, __entry->len, + TP_printk("addr=%s xid=0x%08x len=%d flags=%s", + __get_str(addr), __entry->xid, __entry->len, show_rqstp_flags(__entry->flags)) ); @@ -519,20 +517,18 @@ DECLARE_EVENT_CLASS(svc_rqst_event, TP_STRUCT__entry( __field(u32, xid) __field(unsigned long, flags) - __dynamic_array(unsigned char, addr, rqst->rq_addrlen) + __string(addr, rqst->rq_xprt->xpt_remotebuf) ), TP_fast_assign( __entry->xid = be32_to_cpu(rqst->rq_xid); __entry->flags = rqst->rq_flags; - memcpy(__get_dynamic_array(addr), - &rqst->rq_addr, rqst->rq_addrlen); + __assign_str(addr, rqst->rq_xprt->xpt_remotebuf); ), - TP_printk("addr=%pIScp rq_xid=0x%08x flags=%s", - (struct sockaddr *)__get_dynamic_array(addr), - __entry->xid, - show_rqstp_flags(__entry->flags)) + TP_printk("addr=%s xid=0x%08x flags=%s", + __get_str(addr), __entry->xid, + show_rqstp_flags(__entry->flags)) ); DEFINE_EVENT(svc_rqst_event, svc_defer, @@ -553,21 +549,19 @@ DECLARE_EVENT_CLASS(svc_rqst_status, __field(u32, xid) __field(int, status) __field(unsigned long, flags) - __dynamic_array(unsigned char, addr, rqst->rq_addrlen) + __string(addr, rqst->rq_xprt->xpt_remotebuf) ), TP_fast_assign( __entry->xid = be32_to_cpu(rqst->rq_xid); __entry->status = status; __entry->flags = rqst->rq_flags; - memcpy(__get_dynamic_array(addr), - &rqst->rq_addr, rqst->rq_addrlen); + __assign_str(addr, rqst->rq_xprt->xpt_remotebuf); ), - TP_printk("addr=%pIScp rq_xid=0x%08x status=%d flags=%s", - (struct sockaddr *)__get_dynamic_array(addr), - __entry->xid, - __entry->status, show_rqstp_flags(__entry->flags)) + TP_printk("addr=%s xid=0x%08x status=%d flags=%s", + __get_str(addr), __entry->xid, + __entry->status, show_rqstp_flags(__entry->flags)) ); DEFINE_EVENT(svc_rqst_status, svc_process, @@ -604,26 +598,19 @@ TRACE_EVENT(svc_xprt_do_enqueue, __field(struct svc_xprt *, xprt) __field(int, pid) __field(unsigned long, flags) - __dynamic_array(unsigned char, addr, xprt != NULL ? - xprt->xpt_remotelen : 0) + __string(addr, xprt->xpt_remotebuf) ), TP_fast_assign( __entry->xprt = xprt; __entry->pid = rqst? rqst->rq_task->pid : 0; - if (xprt) { - memcpy(__get_dynamic_array(addr), - &xprt->xpt_remote, - xprt->xpt_remotelen); - __entry->flags = xprt->xpt_flags; - } else - __entry->flags = 0; + __entry->flags = xprt->xpt_flags; + __assign_str(addr, xprt->xpt_remotebuf); ), - TP_printk("xprt=0x%p addr=%pIScp pid=%d flags=%s", __entry->xprt, - __get_dynamic_array_len(addr) != 0 ? - (struct sockaddr *)__get_dynamic_array(addr) : NULL, - __entry->pid, show_svc_xprt_flags(__entry->flags)) + TP_printk("xprt=%p addr=%s pid=%d flags=%s", + __entry->xprt, __get_str(addr), + __entry->pid, show_svc_xprt_flags(__entry->flags)) ); DECLARE_EVENT_CLASS(svc_xprt_event, @@ -634,19 +621,18 @@ DECLARE_EVENT_CLASS(svc_xprt_event, TP_STRUCT__entry( __field(struct svc_xprt *, xprt) __field(unsigned long, flags) - __dynamic_array(unsigned char, addr, xprt->xpt_remotelen) + __string(addr, xprt->xpt_remotebuf) ), TP_fast_assign( __entry->xprt = xprt; __entry->flags = xprt->xpt_flags; - memcpy(__get_dynamic_array(addr), - &xprt->xpt_remote, xprt->xpt_remotelen); + __assign_str(addr, xprt->xpt_remotebuf); ), - TP_printk("xprt=0x%p addr=%pIScp flags=%s", __entry->xprt, - (struct sockaddr *)__get_dynamic_array(addr), - show_svc_xprt_flags(__entry->flags)) + TP_printk("xprt=%p addr=%s flags=%s", + __entry->xprt, __get_str(addr), + show_svc_xprt_flags(__entry->flags)) ); DEFINE_EVENT(svc_xprt_event, svc_xprt_dequeue, @@ -682,25 +668,18 @@ TRACE_EVENT(svc_handle_xprt, __field(struct svc_xprt *, xprt) __field(int, len) __field(unsigned long, flags) - __dynamic_array(unsigned char, addr, xprt != NULL ? - xprt->xpt_remotelen : 0) + __string(addr, xprt->xpt_remotebuf) ), TP_fast_assign( __entry->xprt = xprt; __entry->len = len; - if (xprt) { - memcpy(__get_dynamic_array(addr), - &xprt->xpt_remote, - xprt->xpt_remotelen); - __entry->flags = xprt->xpt_flags; - } else - __entry->flags = 0; + __entry->flags = xprt->xpt_flags; + __assign_str(addr, xprt->xpt_remotebuf); ), - TP_printk("xprt=0x%p addr=%pIScp len=%d flags=%s", __entry->xprt, - __get_dynamic_array_len(addr) != 0 ? - (struct sockaddr *)__get_dynamic_array(addr) : NULL, + TP_printk("xprt=%p addr=%s len=%d flags=%s", + __entry->xprt, __get_str(addr), __entry->len, show_svc_xprt_flags(__entry->flags)) ); @@ -712,18 +691,16 @@ DECLARE_EVENT_CLASS(svc_deferred_event, TP_STRUCT__entry( __field(u32, xid) - __dynamic_array(unsigned char, addr, dr->addrlen) + __string(addr, dr->xprt->xpt_remotebuf) ), TP_fast_assign( __entry->xid = be32_to_cpu(*(__be32 *)(dr->args + (dr->xprt_hlen>>2))); - memcpy(__get_dynamic_array(addr), &dr->addr, dr->addrlen); + __assign_str(addr, dr->xprt->xpt_remotebuf); ), - TP_printk("addr=%pIScp xid=0x%08x", - (struct sockaddr *)__get_dynamic_array(addr), - __entry->xid) + TP_printk("addr=%s xid=0x%08x", __get_str(addr), __entry->xid) ); DEFINE_EVENT(svc_deferred_event, svc_drop_deferred, -- cgit From 0b9547bf6b94317b3f8e2496dc2b44cb6e599b01 Mon Sep 17 00:00:00 2001 From: Chuck Lever Date: Tue, 27 Mar 2018 10:51:22 -0400 Subject: sunrpc: Re-purpose trace_svc_process Currently, trace_svc_process has two call sites: 1. Just after a call to svc_send. svc_send already invokes trace_svc_send with the same arguments just before returning 2. Just before a call to svc_drop. svc_drop already invokes trace_svc_drop with the same arguments just after it is called Therefore trace_svc_process does not provide any additional information not already provided by these other trace points. However, it would be useful to record the incoming RPC procedure. So reuse trace_svc_process for this purpose. Signed-off-by: Chuck Lever Signed-off-by: J. Bruce Fields --- include/trace/events/sunrpc.h | 30 ++++++++++++++++++++++++++---- 1 file changed, 26 insertions(+), 4 deletions(-) (limited to 'include/trace') diff --git a/include/trace/events/sunrpc.h b/include/trace/events/sunrpc.h index 1ec8c4c45766..5a8157c04900 100644 --- a/include/trace/events/sunrpc.h +++ b/include/trace/events/sunrpc.h @@ -508,6 +508,32 @@ TRACE_EVENT(svc_recv, show_rqstp_flags(__entry->flags)) ); +TRACE_EVENT(svc_process, + TP_PROTO(const struct svc_rqst *rqst, const char *name), + + TP_ARGS(rqst, name), + + TP_STRUCT__entry( + __field(u32, xid) + __field(u32, vers) + __field(u32, proc) + __string(service, name) + __string(addr, rqst->rq_xprt->xpt_remotebuf) + ), + + TP_fast_assign( + __entry->xid = be32_to_cpu(rqst->rq_xid); + __entry->vers = rqst->rq_vers; + __entry->proc = rqst->rq_proc; + __assign_str(service, name); + __assign_str(addr, rqst->rq_xprt->xpt_remotebuf); + ), + + TP_printk("addr=%s xid=0x%08x service=%s vers=%u proc=%u", + __get_str(addr), __entry->xid, + __get_str(service), __entry->vers, __entry->proc) +); + DECLARE_EVENT_CLASS(svc_rqst_event, TP_PROTO(struct svc_rqst *rqst), @@ -564,10 +590,6 @@ DECLARE_EVENT_CLASS(svc_rqst_status, __entry->status, show_rqstp_flags(__entry->flags)) ); -DEFINE_EVENT(svc_rqst_status, svc_process, - TP_PROTO(struct svc_rqst *rqst, int status), - TP_ARGS(rqst, status)); - DEFINE_EVENT(svc_rqst_status, svc_send, TP_PROTO(struct svc_rqst *rqst, int status), TP_ARGS(rqst, status)); -- cgit From aaba72cd4e793fbf1c04e06dee3d2c3710339678 Mon Sep 17 00:00:00 2001 From: Chuck Lever Date: Tue, 27 Mar 2018 10:51:39 -0400 Subject: sunrpc: Report per-RPC execution stats Introduce a mechanism to report the server-side execution latency of each RPC. The goal is to enable user space to filter the trace record for latency outliers, build histograms, etc. Signed-off-by: Chuck Lever Signed-off-by: J. Bruce Fields --- 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 5a8157c04900..1b383f71ccd7 100644 --- a/include/trace/events/sunrpc.h +++ b/include/trace/events/sunrpc.h @@ -705,6 +705,27 @@ TRACE_EVENT(svc_handle_xprt, __entry->len, show_svc_xprt_flags(__entry->flags)) ); +TRACE_EVENT(svc_stats_latency, + TP_PROTO(const struct svc_rqst *rqst), + + TP_ARGS(rqst), + + TP_STRUCT__entry( + __field(u32, xid) + __field(unsigned long, execute) + __string(addr, rqst->rq_xprt->xpt_remotebuf) + ), + + TP_fast_assign( + __entry->xid = be32_to_cpu(rqst->rq_xid); + __entry->execute = ktime_to_us(ktime_sub(ktime_get(), + rqst->rq_stime)); + __assign_str(addr, rqst->rq_xprt->xpt_remotebuf); + ), + + TP_printk("addr=%s xid=0x%08x execute-us=%lu", + __get_str(addr), __entry->xid, __entry->execute) +); DECLARE_EVENT_CLASS(svc_deferred_event, TP_PROTO(struct svc_deferred_req *dr), -- cgit From 55f5088c22cc83dbc64394abfbf76cd1ff5e7cd0 Mon Sep 17 00:00:00 2001 From: Chuck Lever Date: Tue, 27 Mar 2018 10:52:27 -0400 Subject: svc: Report xprt dequeue latency Record the time between when a rqstp is enqueued on a transport and when it is dequeued. This includes how long the rqstp waits on the queue and how long it takes the kernel scheduler to wake a nfsd thread to service it. The svc_xprt_dequeue trace point is altered to include the number of microseconds between xprt_enqueue and xprt_dequeue. Signed-off-by: Chuck Lever Signed-off-by: J. Bruce Fields --- include/trace/events/sunrpc.h | 30 ++++++++++++++++++++++++++---- 1 file changed, 26 insertions(+), 4 deletions(-) (limited to 'include/trace') diff --git a/include/trace/events/sunrpc.h b/include/trace/events/sunrpc.h index 1b383f71ccd7..922cb8968fb2 100644 --- a/include/trace/events/sunrpc.h +++ b/include/trace/events/sunrpc.h @@ -657,14 +657,36 @@ DECLARE_EVENT_CLASS(svc_xprt_event, show_svc_xprt_flags(__entry->flags)) ); -DEFINE_EVENT(svc_xprt_event, svc_xprt_dequeue, - TP_PROTO(struct svc_xprt *xprt), - TP_ARGS(xprt)); - DEFINE_EVENT(svc_xprt_event, svc_xprt_no_write_space, TP_PROTO(struct svc_xprt *xprt), TP_ARGS(xprt)); +TRACE_EVENT(svc_xprt_dequeue, + TP_PROTO(struct svc_rqst *rqst), + + TP_ARGS(rqst), + + TP_STRUCT__entry( + __field(struct svc_xprt *, xprt) + __field(unsigned long, flags) + __field(unsigned long, wakeup) + __string(addr, rqst->rq_xprt->xpt_remotebuf) + ), + + TP_fast_assign( + __entry->xprt = rqst->rq_xprt; + __entry->flags = rqst->rq_xprt->xpt_flags; + __entry->wakeup = ktime_to_us(ktime_sub(ktime_get(), + rqst->rq_qtime)); + __assign_str(addr, rqst->rq_xprt->xpt_remotebuf); + ), + + TP_printk("xprt=%p addr=%s flags=%s wakeup-us=%lu", + __entry->xprt, __get_str(addr), + show_svc_xprt_flags(__entry->flags), + __entry->wakeup) +); + TRACE_EVENT(svc_wake_up, TP_PROTO(int pid), -- cgit