2015-08-26 12:41:12

by Pratyush Anand

Subject: [PATCH V2] net: sunrpc: fix tracepoint Warning: unknown op '->'

`perf stat -e sunrpc:svc_xprt_do_enqueue true` results in

Warning: unknown op '->'
Warning: [sunrpc:svc_xprt_do_enqueue] unknown op '->'

Similar warning for svc_handle_xprt as well.

Actually TP_printk() should never dereference an address saved in the ring
buffer that points somewhere in the kernel. There's no guarantee that that
object still exists (with the exception of static strings).

Therefore change all the arguments for TP_printk(), so that it references
values existing in the ring buffer only.

While doing that, also fix another possible bug when argument xprt could be
NULL and TP_fast_assign() tries to access it's elements.

Signed-off-by: Pratyush Anand <[email protected]>
Acked-by: Steven Rostedt <[email protected]>
---
Changes since V1:
- struct sockaddr memcopied to ring buffer so that its internal element can
be accessed while printing %pIS.

include/trace/events/sunrpc.h | 23 ++++++++++++++++-------
1 file changed, 16 insertions(+), 7 deletions(-)

diff --git a/include/trace/events/sunrpc.h b/include/trace/events/sunrpc.h
index fd1a02cb3c82..75a16fcc0795 100644
--- a/include/trace/events/sunrpc.h
+++ b/include/trace/events/sunrpc.h
@@ -529,18 +529,23 @@ TRACE_EVENT(svc_xprt_do_enqueue,

TP_STRUCT__entry(
__field(struct svc_xprt *, xprt)
+ __field_struct(struct sockaddr_storage, ss)
__field(struct svc_rqst *, rqst)
+ __field(int, pid)
+ __field(unsigned long, flags)
),

TP_fast_assign(
- __entry->xprt = xprt;
+ __entry->xprt = xprt,
+ xprt ? memcpy(&__entry->ss, &xprt->xpt_remote, sizeof(__entry->ss)) : memset(&__entry->ss, 0, sizeof(__entry->ss));
__entry->rqst = rqst;
+ __entry->pid = rqst? rqst->rq_task->pid : 0;
+ __entry->flags = xprt ? xprt->xpt_flags : 0;
),

TP_printk("xprt=0x%p addr=%pIScp pid=%d flags=%s", __entry->xprt,
- (struct sockaddr *)&__entry->xprt->xpt_remote,
- __entry->rqst ? __entry->rqst->rq_task->pid : 0,
- show_svc_xprt_flags(__entry->xprt->xpt_flags))
+ (struct sockaddr *)&__entry->ss,
+ __entry->pid, show_svc_xprt_flags(__entry->flags))
);

TRACE_EVENT(svc_xprt_dequeue,
@@ -589,16 +594,20 @@ TRACE_EVENT(svc_handle_xprt,
TP_STRUCT__entry(
__field(struct svc_xprt *, xprt)
__field(int, len)
+ __field_struct(struct sockaddr_storage, ss)
+ __field(unsigned long, flags)
),

TP_fast_assign(
- __entry->xprt = xprt;
+ __entry->xprt = xprt,
+ xprt ? memcpy(&__entry->ss, &xprt->xpt_remote, sizeof(__entry->ss)) : memset(&__entry->ss, 0, sizeof(__entry->ss));
__entry->len = len;
+ __entry->flags = xprt ? xprt->xpt_flags : 0;
),

TP_printk("xprt=0x%p addr=%pIScp len=%d flags=%s", __entry->xprt,
- (struct sockaddr *)&__entry->xprt->xpt_remote, __entry->len,
- show_svc_xprt_flags(__entry->xprt->xpt_flags))
+ (struct sockaddr *)&__entry->ss,
+ __entry->len, show_svc_xprt_flags(__entry->flags))
);
#endif /* _TRACE_SUNRPC_H */

--
2.4.3

2015-08-26 13:13:08

by Jeff Layton

Subject: Re: [PATCH V2] net: sunrpc: fix tracepoint Warning: unknown op '->'

On Wed, 26 Aug 2015 18:10:44 +0530
Pratyush Anand <[email protected]> wrote:

> `perf stat -e sunrpc:svc_xprt_do_enqueue true` results in
>
> Warning: unknown op '->'
> Warning: [sunrpc:svc_xprt_do_enqueue] unknown op '->'
>
> Similar warning for svc_handle_xprt as well.
>
> Actually TP_printk() should never dereference an address saved in the ring
> buffer that points somewhere in the kernel. There's no guarantee that that
> object still exists (with the exception of static strings).
>
> Therefore change all the arguments for TP_printk(), so that it references
> values existing in the ring buffer only.
>
> While doing that, also fix another possible bug when argument xprt could be
> NULL and TP_fast_assign() tries to access it's elements.
>
> Signed-off-by: Pratyush Anand <[email protected]>
> Acked-by: Steven Rostedt <[email protected]>
> ---
> Changes since V1:
> - struct sockaddr memcopied to ring buffer so that its internal element can
> be accessed while printing %pIS.
>
> include/trace/events/sunrpc.h | 23 ++++++++++++++++-------
> 1 file changed, 16 insertions(+), 7 deletions(-)
>
> diff --git a/include/trace/events/sunrpc.h b/include/trace/events/sunrpc.h
> index fd1a02cb3c82..75a16fcc0795 100644
> --- a/include/trace/events/sunrpc.h
> +++ b/include/trace/events/sunrpc.h
> @@ -529,18 +529,23 @@ TRACE_EVENT(svc_xprt_do_enqueue,
>
> TP_STRUCT__entry(
> __field(struct svc_xprt *, xprt)
> + __field_struct(struct sockaddr_storage, ss)
> __field(struct svc_rqst *, rqst)

nit: I think you should be able to avoid storing "rqst" now.

> + __field(int, pid)
> + __field(unsigned long, flags)
> ),
>
> TP_fast_assign(
> - __entry->xprt = xprt;
> + __entry->xprt = xprt,

Shouldn't that line end with ';'?

> + xprt ? memcpy(&__entry->ss, &xprt->xpt_remote, sizeof(__entry->ss)) : memset(&__entry->ss, 0, sizeof(__entry->ss));
> __entry->rqst = rqst;
> + __entry->pid = rqst? rqst->rq_task->pid : 0;
> + __entry->flags = xprt ? xprt->xpt_flags : 0;
> ),
>
> TP_printk("xprt=0x%p addr=%pIScp pid=%d flags=%s", __entry->xprt,
> - (struct sockaddr *)&__entry->xprt->xpt_remote,
> - __entry->rqst ? __entry->rqst->rq_task->pid : 0,
> - show_svc_xprt_flags(__entry->xprt->xpt_flags))
> + (struct sockaddr *)&__entry->ss,
> + __entry->pid, show_svc_xprt_flags(__entry->flags))
> );
>
> TRACE_EVENT(svc_xprt_dequeue,
> @@ -589,16 +594,20 @@ TRACE_EVENT(svc_handle_xprt,
> TP_STRUCT__entry(
> __field(struct svc_xprt *, xprt)
> __field(int, len)
> + __field_struct(struct sockaddr_storage, ss)
> + __field(unsigned long, flags)
> ),
>
> TP_fast_assign(
> - __entry->xprt = xprt;
> + __entry->xprt = xprt,
> + xprt ? memcpy(&__entry->ss, &xprt->xpt_remote, sizeof(__entry->ss)) : memset(&__entry->ss, 0, sizeof(__entry->ss));
> __entry->len = len;
> + __entry->flags = xprt ? xprt->xpt_flags : 0;
> ),
>
> TP_printk("xprt=0x%p addr=%pIScp len=%d flags=%s", __entry->xprt,
> - (struct sockaddr *)&__entry->xprt->xpt_remote, __entry->len,
> - show_svc_xprt_flags(__entry->xprt->xpt_flags))
> + (struct sockaddr *)&__entry->ss,
> + __entry->len, show_svc_xprt_flags(__entry->flags))
> );
> #endif /* _TRACE_SUNRPC_H */
>

Looks good otherwise. Thanks for fixing this!

Reviewed-by: Jeff Layton <[email protected]>

2015-08-26 13:53:01

by Pratyush Anand

Subject: Re: [PATCH V2] net: sunrpc: fix tracepoint Warning: unknown op '->'

On 26/08/2015:09:13:02 AM, Jeff Layton wrote:
> On Wed, 26 Aug 2015 18:10:44 +0530
> Pratyush Anand <[email protected]> wrote:
>
> > `perf stat -e sunrpc:svc_xprt_do_enqueue true` results in
> >
> > Warning: unknown op '->'
> > Warning: [sunrpc:svc_xprt_do_enqueue] unknown op '->'
> >
> > Similar warning for svc_handle_xprt as well.
> >
> > Actually TP_printk() should never dereference an address saved in the ring
> > buffer that points somewhere in the kernel. There's no guarantee that that
> > object still exists (with the exception of static strings).
> >
> > Therefore change all the arguments for TP_printk(), so that it references
> > values existing in the ring buffer only.
> >
> > While doing that, also fix another possible bug when argument xprt could be
> > NULL and TP_fast_assign() tries to access it's elements.
> >
> > Signed-off-by: Pratyush Anand <[email protected]>
> > Acked-by: Steven Rostedt <[email protected]>
> > ---
> > Changes since V1:
> > - struct sockaddr memcopied to ring buffer so that its internal element can
> > be accessed while printing %pIS.
> >
> > include/trace/events/sunrpc.h | 23 ++++++++++++++++-------
> > 1 file changed, 16 insertions(+), 7 deletions(-)
> >
> > diff --git a/include/trace/events/sunrpc.h b/include/trace/events/sunrpc.h
> > index fd1a02cb3c82..75a16fcc0795 100644
> > --- a/include/trace/events/sunrpc.h
> > +++ b/include/trace/events/sunrpc.h
> > @@ -529,18 +529,23 @@ TRACE_EVENT(svc_xprt_do_enqueue,
> >
> > TP_STRUCT__entry(
> > __field(struct svc_xprt *, xprt)
> > + __field_struct(struct sockaddr_storage, ss)
> > __field(struct svc_rqst *, rqst)
>
> nit: I think you should be able to avoid storing "rqst" now.

Yes.

>
> > + __field(int, pid)
> > + __field(unsigned long, flags)
> > ),
> >
> > TP_fast_assign(
> > - __entry->xprt = xprt;
> > + __entry->xprt = xprt,
>
> Shouldn't that line end with ';'?
>

I think, both should be OK.. I just copied this hunk from svc_xprt_dequeue.

> > + xprt ? memcpy(&__entry->ss, &xprt->xpt_remote, sizeof(__entry->ss)) : memset(&__entry->ss, 0, sizeof(__entry->ss));
> > __entry->rqst = rqst;
> > + __entry->pid = rqst? rqst->rq_task->pid : 0;
> > + __entry->flags = xprt ? xprt->xpt_flags : 0;
> > ),
> >
> > TP_printk("xprt=0x%p addr=%pIScp pid=%d flags=%s", __entry->xprt,
> > - (struct sockaddr *)&__entry->xprt->xpt_remote,
> > - __entry->rqst ? __entry->rqst->rq_task->pid : 0,
> > - show_svc_xprt_flags(__entry->xprt->xpt_flags))
> > + (struct sockaddr *)&__entry->ss,
> > + __entry->pid, show_svc_xprt_flags(__entry->flags))
> > );
> >
> > TRACE_EVENT(svc_xprt_dequeue,
> > @@ -589,16 +594,20 @@ TRACE_EVENT(svc_handle_xprt,
> > TP_STRUCT__entry(
> > __field(struct svc_xprt *, xprt)
> > __field(int, len)
> > + __field_struct(struct sockaddr_storage, ss)
> > + __field(unsigned long, flags)
> > ),
> >
> > TP_fast_assign(
> > - __entry->xprt = xprt;
> > + __entry->xprt = xprt,
> > + xprt ? memcpy(&__entry->ss, &xprt->xpt_remote, sizeof(__entry->ss)) : memset(&__entry->ss, 0, sizeof(__entry->ss));
> > __entry->len = len;
> > + __entry->flags = xprt ? xprt->xpt_flags : 0;
> > ),
> >
> > TP_printk("xprt=0x%p addr=%pIScp len=%d flags=%s", __entry->xprt,
> > - (struct sockaddr *)&__entry->xprt->xpt_remote, __entry->len,
> > - show_svc_xprt_flags(__entry->xprt->xpt_flags))
> > + (struct sockaddr *)&__entry->ss,
> > + __entry->len, show_svc_xprt_flags(__entry->flags))
> > );
> > #endif /* _TRACE_SUNRPC_H */
> >
>
> Looks good otherwise. Thanks for fixing this!
>
> Reviewed-by: Jeff Layton <[email protected]>

Thanks :-)

~Pratyush