net: sunrpc: trace fixes

PATCH Superseded Pratyush Anand 3 participants 10 messages Aug 25, 2015 – Aug 26, 2015

Subsystems (3)

NFS client NFS server Tracing

lore

Share & tools

lore

Pratyush Anand

author

2015-08-25 06:04 UTC #0 lore raw

cover net: sunrpc: trace fixes

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(-)

Signature · 1 line

2.4.3

Pratyush Anand

author

2015-08-25 06:05 UTC #1 lore raw

PATCH 1/2 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]>

Cc Steven Rostedt <[email protected]>

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

include/trace/events/sunrpc.h +16 -5

index fd1a02cb3c82..937e482d80e9 100644
@@ -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 */

Signature · 1 line

2.4.3

Steven Rostedt

maintainer Acked-by on v1 1/2

2015-08-25 14:03 UTC #2 lore raw

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

Quoted 10 lines · On Tue, 25 Aug 2015 11:34:19 +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).

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

Quoted 9 lines

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]>
Cc Steven Rostedt <[email protected]>

Acked-by Steven Rostedt <[email protected]>

-- Steve

Quoted 60 lines

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

include/trace/events/sunrpc.h +16 -5

index fd1a02cb3c82..937e482d80e9 100644
@@ -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 */

Jeff Layton

2015-08-26 10:31 UTC #3 lore raw

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

In reply to Pratyush Anand

Quoted 31 lines · On Tue, 25 Aug 2015 11:34:19 +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]>
Cc Steven Rostedt <[email protected]>
---
 include/trace/events/sunrpc.h | 21 ++++++++++++++++-----
 1 file changed, 16 insertions(+), 5 deletions(-)
include/trace/events/sunrpc.h +0 -0
index fd1a02cb3c82..937e482d80e9 100644
@@ -529,18 +529,24 @@ TRACE_EVENT(svc_xprt_do_enqueue,
 
 	TP_STRUCT__entry(
 		__field(struct svc_xprt *, xprt)

include/trace/events/sunrpc.h TRACE_EVENT(svc_xprt_do_enqueue, · line 541

Quoted 10 lines

include/trace/events/sunrpc.h +5 -0

+		__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.

Quoted 41 lines

include/trace/events/sunrpc.h +4 -3

 		__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,

include/trace/events/sunrpc.h +7 -2

@@ -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 */

Signature · 1 line

Jeff Layton <[email protected]>

Pratyush Anand

author

2015-08-26 11:52 UTC #4 lore raw

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

Hi Jeff,

Thanks for your review comments.

Quoted 11 lines · Jeff Layton

include/trace/events/sunrpc.h TRACE_EVENT(svc_xprt_do_enqueue, · line 541
Quoted 4 lines · On Tue, 25 Aug 2015 11:34:19 +0530 Pratyush Anand <[email protected]> wrote:
include/trace/events/sunrpc.h +2 -0
 	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.

Quoted 5 lines

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

Jeff Layton

2015-08-26 12:01 UTC #5 lore raw

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

Quoted 31 lines · On Wed, 26 Aug 2015 17:22:25 +0530 Pratyush Anand <[email protected]> wrote:

Hi Jeff,
Thanks for your review comments.
Quoted 11 lines · Jeff Layton
include/trace/events/sunrpc.h TRACE_EVENT(svc_xprt_do_enqueue, · line 541
Quoted 4 lines · On Tue, 25 Aug 2015 11:34:19 +0530 Pratyush Anand <[email protected]> wrote:
include/trace/events/sunrpc.h +2 -0
 	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.
Quoted 5 lines
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.

Quoted 4 lines

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.

Signature · 1 line

Jeff Layton <[email protected]>

Pratyush Anand

author

2015-08-26 12:11 UTC #6 lore raw

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

Quoted 34 lines · Jeff Layton

Quoted 31 lines · On Wed, 26 Aug 2015 17:22:25 +0530 Pratyush Anand <[email protected]> wrote:
Hi Jeff,
Thanks for your review comments.
Quoted 11 lines · Jeff Layton
include/trace/events/sunrpc.h TRACE_EVENT(svc_xprt_do_enqueue, · line 541
Quoted 4 lines · On Tue, 25 Aug 2015 11:34:19 +0530 Pratyush Anand <[email protected]> wrote:
include/trace/events/sunrpc.h +2 -0
 	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.
Quoted 5 lines
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.

Quoted 6 lines

Quoted 4 lines
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

Pratyush Anand

author

2015-08-25 06:05 UTC #7 lore raw

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

In reply to 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 <[email protected]>

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

include/trace/events/sunrpc.h +5 -5

index 937e482d80e9..37b6af1a911a 100644
@@ -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,

Signature · 1 line

2.4.3

Jeff Layton

NAK

2015-08-26 10:32 UTC #8 lore raw

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

Quoted 20 lines · On Tue, 25 Aug 2015 11:34:20 +0530 Pratyush Anand <[email protected]> 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 <[email protected]>
---
 include/trace/events/sunrpc.h | 10 +++++-----
 1 file changed, 5 insertions(+), 5 deletions(-)
include/trace/events/sunrpc.h +0 -1
index 937e482d80e9..37b6af1a911a 100644
@@ -556,19 +556,19 @@ TRACE_EVENT(svc_xprt_dequeue,
 
 	TP_STRUCT__entry(
 		__field(struct svc_xprt *, xprt)
-		__field_struct(struct sockaddr_storage, ss)

include/trace/events/sunrpc.h TRACE_EVENT(svc_xprt_dequeue, · line 566

Quoted 10 lines

include/trace/events/sunrpc.h +4 -2

+		__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.

Quoted 10 lines

include/trace/events/sunrpc.h +1 -2

 		__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,

Signature · 1 line

Jeff Layton <[email protected]>

Steven Rostedt

maintainer

2015-08-26 20:30 UTC #9 lore raw

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

Quoted 8 lines · On Wed, 26 Aug 2015 06:32:55 -0400 Jeff Layton <[email protected]> wrote:

include/trace/events/sunrpc.h TRACE_EVENT(svc_xprt_dequeue, · line 566
Quoted 6 lines
include/trace/events/sunrpc.h +3 -2
 	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.

Quoted 2 lines

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

Quoted 13 lines

Quoted 11 lines

include/trace/events/sunrpc.h +1 -2

 		__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,