[PATCH 0/2] net: sunrpc: trace fixes

[PATCH 0/2] net: sunrpc: trace fixes

[Pratyush Anand]

This patchset fixes few bugs with sunrpc trace implementation.

Pratyush Anand (2):
  net: sunrpc: fix tracepoint Warning: unknown op '->'
  net: sunrpc: fix trace print of &xprt->xpt_remote

 include/trace/events/sunrpc.h | 31 +++++++++++++++++++++----------
 1 file changed, 21 insertions(+), 10 deletions(-)

-- 
2.4.3

[PATCH 1/2] net: sunrpc: fix tracepoint Warning: unknown op '->'

[Pratyush Anand]

`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 <panand@redhat.com>
Cc: Steven Rostedt <rostedt@goodmis.org>
---
 include/trace/events/sunrpc.h | 21 ++++++++++++++++-----
 1 file changed, 16 insertions(+), 5 deletions(-)

diff --git a/include/trace/events/sunrpc.h b/include/trace/events/sunrpc.h
index fd1a02cb3c82..937e482d80e9 100644
--- a/include/trace/events/sunrpc.h
+++ b/include/trace/events/sunrpc.h
@@ -529,18 +529,24 @@ TRACE_EVENT(svc_xprt_do_enqueue,
 
 	TP_STRUCT__entry(
 		__field(struct svc_xprt *, xprt)
+		__field(struct sockaddr *, addr)
 		__field(struct svc_rqst *, rqst)
+		__field(int, pid)
+		__field(unsigned long, flags)
 	),
 
 	TP_fast_assign(
 		__entry->xprt = xprt;
+		__entry->addr =
+			xprt ? (struct sockaddr *)&xprt->xpt_remote : NULL;
 		__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))
+		__entry->addr, __entry->pid,
+		show_svc_xprt_flags(__entry->flags))
 );
 
 TRACE_EVENT(svc_xprt_dequeue,
@@ -589,16 +595,21 @@ TRACE_EVENT(svc_handle_xprt,
 	TP_STRUCT__entry(
 		__field(struct svc_xprt *, xprt)
 		__field(int, len)
+		__field(struct sockaddr *, addr)
+		__field(unsigned long, flags)
 	),
 
 	TP_fast_assign(
 		__entry->xprt = xprt;
+		__entry->addr =
+			xprt ? (struct sockaddr *)&xprt->xpt_remote : NULL;
 		__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))
+		__entry->addr, __entry->len,
+		show_svc_xprt_flags(__entry->flags))
 );
 #endif /* _TRACE_SUNRPC_H */
 
-- 
2.4.3

Re: [PATCH 1/2] net: sunrpc: fix tracepoint Warning: unknown op '->'

[Steven Rostedt]

On Tue, 25 Aug 2015 11:34:19 +0530
Pratyush Anand <panand@redhat.com> 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).

Right, that is very dangerous. It has caused kernel panics in the past.

> 
> 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 <panand@redhat.com>
> Cc: Steven Rostedt <rostedt@goodmis.org>

Acked-by: Steven Rostedt <rostedt@goodmis.org>

-- Steve

> ---
>  include/trace/events/sunrpc.h | 21 ++++++++++++++++-----
>  1 file changed, 16 insertions(+), 5 deletions(-)
> 
> diff --git a/include/trace/events/sunrpc.h b/include/trace/events/sunrpc.h
> index fd1a02cb3c82..937e482d80e9 100644
> --- a/include/trace/events/sunrpc.h
> +++ b/include/trace/events/sunrpc.h
> @@ -529,18 +529,24 @@ TRACE_EVENT(svc_xprt_do_enqueue,
>  
>  	TP_STRUCT__entry(
>  		__field(struct svc_xprt *, xprt)
> +		__field(struct sockaddr *, addr)
>  		__field(struct svc_rqst *, rqst)
> +		__field(int, pid)
> +		__field(unsigned long, flags)
>  	),
>  
>  	TP_fast_assign(
>  		__entry->xprt = xprt;
> +		__entry->addr =
> +			xprt ? (struct sockaddr *)&xprt->xpt_remote : NULL;
>  		__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))
> +		__entry->addr, __entry->pid,
> +		show_svc_xprt_flags(__entry->flags))
>  );
>  
>  TRACE_EVENT(svc_xprt_dequeue,
> @@ -589,16 +595,21 @@ TRACE_EVENT(svc_handle_xprt,
>  	TP_STRUCT__entry(
>  		__field(struct svc_xprt *, xprt)
>  		__field(int, len)
> +		__field(struct sockaddr *, addr)
> +		__field(unsigned long, flags)
>  	),
>  
>  	TP_fast_assign(
>  		__entry->xprt = xprt;
> +		__entry->addr =
> +			xprt ? (struct sockaddr *)&xprt->xpt_remote : NULL;
>  		__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))
> +		__entry->addr, __entry->len,
> +		show_svc_xprt_flags(__entry->flags))
>  );
>  #endif /* _TRACE_SUNRPC_H */
>  

Re: [PATCH 1/2] net: sunrpc: fix tracepoint Warning: unknown op '->'

[Jeff Layton]

On Tue, 25 Aug 2015 11:34:19 +0530
Pratyush Anand <panand@redhat.com> 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 <panand@redhat.com>
> Cc: Steven Rostedt <rostedt@goodmis.org>
> ---
>  include/trace/events/sunrpc.h | 21 ++++++++++++++++-----
>  1 file changed, 16 insertions(+), 5 deletions(-)
> 
> diff --git a/include/trace/events/sunrpc.h b/include/trace/events/sunrpc.h
> index fd1a02cb3c82..937e482d80e9 100644
> --- a/include/trace/events/sunrpc.h
> +++ b/include/trace/events/sunrpc.h
> @@ -529,18 +529,24 @@ TRACE_EVENT(svc_xprt_do_enqueue,
>  
>  	TP_STRUCT__entry(
>  		__field(struct svc_xprt *, xprt)
> +		__field(struct sockaddr *, addr)
>  		__field(struct svc_rqst *, rqst)
> +		__field(int, pid)
> +		__field(unsigned long, flags)
>  	),
>  
>  	TP_fast_assign(
>  		__entry->xprt = xprt;
> +		__entry->addr =
> +			xprt ? (struct sockaddr *)&xprt->xpt_remote : NULL;

I don't get it. It's not safe to save a pointer to xprt and dereference
that in a tracepoint (and I understand why that is), but it is safe to
save a pointer to a structure embedded inside of xprt? Shouldn't you be
saving a copy of the entire sockaddr struct instead?

Ahh, ok -- I think I see the confusion. %pIScp does not print the
address of the sockaddr, but instead dereferences the pointer and
prints it as a formatted address string. See pointer() in
lib/vsprintf.c. You do want to save off a copy of the structure instead.

>  		__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))
> +		__entry->addr, __entry->pid,
> +		show_svc_xprt_flags(__entry->flags))
>  );
>  
>  TRACE_EVENT(svc_xprt_dequeue,
> @@ -589,16 +595,21 @@ TRACE_EVENT(svc_handle_xprt,
>  	TP_STRUCT__entry(
>  		__field(struct svc_xprt *, xprt)
>  		__field(int, len)
> +		__field(struct sockaddr *, addr)
> +		__field(unsigned long, flags)
>  	),
>  
>  	TP_fast_assign(
>  		__entry->xprt = xprt;
> +		__entry->addr =
> +			xprt ? (struct sockaddr
> *)&xprt->xpt_remote : NULL; __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))
> +		__entry->addr, __entry->len,
> +		show_svc_xprt_flags(__entry->flags))
>  );
>  #endif /* _TRACE_SUNRPC_H */
>  


-- 
Jeff Layton <jlayton@poochiereds.net>

Re: [PATCH 1/2] net: sunrpc: fix tracepoint Warning: unknown op '->'

[Pratyush Anand]

Hi Jeff,

Thanks for your review comments.

On 26/08/2015:06:31:03 AM, Jeff Layton wrote:
> On Tue, 25 Aug 2015 11:34:19 +0530
> Pratyush Anand <panand@redhat.com> wrote:
> >  	TP_fast_assign(
> >  		__entry->xprt = xprt;
> > +		__entry->addr =
> > +			xprt ? (struct sockaddr *)&xprt->xpt_remote : NULL;
> 
> I don't get it. It's not safe to save a pointer to xprt and dereference
> that in a tracepoint (and I understand why that is), but it is safe to
> save a pointer to a structure embedded inside of xprt? Shouldn't you be
> saving a copy of the entire sockaddr struct instead?

As far as "saving of a pointer to a structure embedded inside of xprt" is
concerned, I do not see any issue.

Its your take that what you want to print as your tracepoint print output. I
might be missing something..  However, I do not see any value addition in
printing address of a structure(located in ring buffer) where xprt->xpt_remote
has been copied.

> 
> Ahh, ok -- I think I see the confusion. %pIScp does not print the
> address of the sockaddr, but instead dereferences the pointer and
> prints it as a formatted address string. See pointer() in
> lib/vsprintf.c. You do want to save off a copy of the structure instead.

In my opinion, saving of structure would only be necessary if you want to access
element of the structure xprt->xpt_remote.

~Pratyush

Re: [PATCH 1/2] net: sunrpc: fix tracepoint Warning: unknown op '->'

[Jeff Layton]

On Wed, 26 Aug 2015 17:22:25 +0530
Pratyush Anand <panand@redhat.com> wrote:

> Hi Jeff,
> 
> Thanks for your review comments.
> 
> On 26/08/2015:06:31:03 AM, Jeff Layton wrote:
> > On Tue, 25 Aug 2015 11:34:19 +0530
> > Pratyush Anand <panand@redhat.com> wrote:
> > >  	TP_fast_assign(
> > >  		__entry->xprt = xprt;
> > > +		__entry->addr =
> > > +			xprt ? (struct sockaddr *)&xprt->xpt_remote : NULL;
> > 
> > I don't get it. It's not safe to save a pointer to xprt and dereference
> > that in a tracepoint (and I understand why that is), but it is safe to
> > save a pointer to a structure embedded inside of xprt? Shouldn't you be
> > saving a copy of the entire sockaddr struct instead?
> 
> As far as "saving of a pointer to a structure embedded inside of xprt" is
> concerned, I do not see any issue.
> 
> Its your take that what you want to print as your tracepoint print output. I
> might be missing something..  However, I do not see any value addition in
> printing address of a structure(located in ring buffer) where xprt->xpt_remote
> has been copied.
> 
> > 
> > Ahh, ok -- I think I see the confusion. %pIScp does not print the
> > address of the sockaddr, but instead dereferences the pointer and
> > prints it as a formatted address string. See pointer() in
> > lib/vsprintf.c. You do want to save off a copy of the structure instead.
> 
> In my opinion, saving of structure would only be necessary if you want to access
> element of the structure xprt->xpt_remote.
> 
> ~Pratyush

That's exactly what %pI does. Look at the pointer() function.

For this tracepoint, we want to print out the address of the remote end
of the socket. That's saved in xprt->xpt_remote.

%pIScp doesn't print the pointer's address. It dereferences that
pointer and formats and prints the socket address that it points to. If
you pass a NULL pointer into anything that uses %pI, it's going to oops.

-- 
Jeff Layton <jlayton@poochiereds.net>

Re: [PATCH 1/2] net: sunrpc: fix tracepoint Warning: unknown op '->'

[Pratyush Anand]

On 26/08/2015:08:01:21 AM, Jeff Layton wrote:
> On Wed, 26 Aug 2015 17:22:25 +0530
> Pratyush Anand <panand@redhat.com> wrote:
> 
> > Hi Jeff,
> > 
> > Thanks for your review comments.
> > 
> > On 26/08/2015:06:31:03 AM, Jeff Layton wrote:
> > > On Tue, 25 Aug 2015 11:34:19 +0530
> > > Pratyush Anand <panand@redhat.com> wrote:
> > > >  	TP_fast_assign(
> > > >  		__entry->xprt = xprt;
> > > > +		__entry->addr =
> > > > +			xprt ? (struct sockaddr *)&xprt->xpt_remote : NULL;
> > > 
> > > I don't get it. It's not safe to save a pointer to xprt and dereference
> > > that in a tracepoint (and I understand why that is), but it is safe to
> > > save a pointer to a structure embedded inside of xprt? Shouldn't you be
> > > saving a copy of the entire sockaddr struct instead?
> > 
> > As far as "saving of a pointer to a structure embedded inside of xprt" is
> > concerned, I do not see any issue.
> > 
> > Its your take that what you want to print as your tracepoint print output. I
> > might be missing something..  However, I do not see any value addition in
> > printing address of a structure(located in ring buffer) where xprt->xpt_remote
> > has been copied.
> > 
> > > 
> > > Ahh, ok -- I think I see the confusion. %pIScp does not print the
> > > address of the sockaddr, but instead dereferences the pointer and
> > > prints it as a formatted address string. See pointer() in
> > > lib/vsprintf.c. You do want to save off a copy of the structure instead.
> > 
> > In my opinion, saving of structure would only be necessary if you want to access
> > element of the structure xprt->xpt_remote.
> > 
> > ~Pratyush
> 
> That's exactly what %pI does. Look at the pointer() function.

My bad..am a slow learner :(
Will send V2. Thanks for explaining.

~Pratyush

[PATCH 2/2] net: sunrpc: fix trace print of &xprt->xpt_remote

[Pratyush Anand]

TP_printk() for svc_xprt_dequeue intends to print address of
xprt->xpt_remote, however it prints address of another structure where
xprt->xpt_remote has been copied.

This patch fixes the above behaviour.

Signed-off-by: Pratyush Anand <panand@redhat.com>
---
 include/trace/events/sunrpc.h | 10 +++++-----
 1 file changed, 5 insertions(+), 5 deletions(-)

diff --git a/include/trace/events/sunrpc.h b/include/trace/events/sunrpc.h
index 937e482d80e9..37b6af1a911a 100644
--- a/include/trace/events/sunrpc.h
+++ b/include/trace/events/sunrpc.h
@@ -556,19 +556,19 @@ TRACE_EVENT(svc_xprt_dequeue,
 
 	TP_STRUCT__entry(
 		__field(struct svc_xprt *, xprt)
-		__field_struct(struct sockaddr_storage, ss)
+		__field(struct sockaddr *, addr)
 		__field(unsigned long, flags)
 	),
 
 	TP_fast_assign(
-		__entry->xprt = xprt,
-		xprt ? memcpy(&__entry->ss, &xprt->xpt_remote, sizeof(__entry->ss)) : memset(&__entry->ss, 0, sizeof(__entry->ss));
+		__entry->xprt = xprt;
+		__entry->addr =
+			xprt ? (struct sockaddr *)&xprt->xpt_remote : NULL;
 		__entry->flags = xprt ? xprt->xpt_flags : 0;
 	),
 
 	TP_printk("xprt=0x%p addr=%pIScp flags=%s", __entry->xprt,
-		(struct sockaddr *)&__entry->ss,
-		show_svc_xprt_flags(__entry->flags))
+		__entry->addr, show_svc_xprt_flags(__entry->flags))
 );
 
 TRACE_EVENT(svc_wake_up,
-- 
2.4.3

Re: [PATCH 2/2] net: sunrpc: fix trace print of &xprt->xpt_remote

[Jeff Layton]

On Tue, 25 Aug 2015 11:34:20 +0530
Pratyush Anand <panand@redhat.com> wrote:

> TP_printk() for svc_xprt_dequeue intends to print address of
> xprt->xpt_remote, however it prints address of another structure where
> xprt->xpt_remote has been copied.
> 
> This patch fixes the above behaviour.
> 
> Signed-off-by: Pratyush Anand <panand@redhat.com>
> ---
>  include/trace/events/sunrpc.h | 10 +++++-----
>  1 file changed, 5 insertions(+), 5 deletions(-)
> 
> diff --git a/include/trace/events/sunrpc.h b/include/trace/events/sunrpc.h
> index 937e482d80e9..37b6af1a911a 100644
> --- a/include/trace/events/sunrpc.h
> +++ b/include/trace/events/sunrpc.h
> @@ -556,19 +556,19 @@ TRACE_EVENT(svc_xprt_dequeue,
>  
>  	TP_STRUCT__entry(
>  		__field(struct svc_xprt *, xprt)
> -		__field_struct(struct sockaddr_storage, ss)
> +		__field(struct sockaddr *, addr)
>  		__field(unsigned long, flags)
>  	),
>  
>  	TP_fast_assign(
> -		__entry->xprt = xprt,
> -		xprt ? memcpy(&__entry->ss, &xprt->xpt_remote, sizeof(__entry->ss)) : memset(&__entry->ss, 0, sizeof(__entry->ss));
> +		__entry->xprt = xprt;
> +		__entry->addr =
> +			xprt ? (struct sockaddr *)&xprt->xpt_remote : NULL;

NAK, this is wrong. %pIScp will dereference that address so you don't
want to pass a NULL pointer to it. We do want to save a copy of the
sockaddr.

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


-- 
Jeff Layton <jlayton@poochiereds.net>

Re: [PATCH 2/2] net: sunrpc: fix trace print of &xprt->xpt_remote

[Steven Rostedt]

On Wed, 26 Aug 2015 06:32:55 -0400
Jeff Layton <jlayton@poochiereds.net> wrote:

 
> >  	TP_fast_assign(
> > -		__entry->xprt = xprt,
> > -		xprt ? memcpy(&__entry->ss, &xprt->xpt_remote, sizeof(__entry->ss)) : memset(&__entry->ss, 0, sizeof(__entry->ss));
> > +		__entry->xprt = xprt;
> > +		__entry->addr =
> > +			xprt ? (struct sockaddr *)&xprt->xpt_remote : NULL;
> 
> NAK, this is wrong. %pIScp will dereference that address so you don't

Ug, I hate that printk option. It can be dangerous.

> want to pass a NULL pointer to it. We do want to save a copy of the
> sockaddr.

Save just enough for what you need to print out. Don't waste any space
on the ring buffer that isn't necessary.

-- Steve

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