diff mbox series

[3/4] SUNRPC: Replace dprintk() call site in xs_data_ready

Message ID 165851074247.361126.17205394769981595871.stgit@morisot.1015granger.net (mailing list archive)
State New, archived
Headers show
Series Pre-requisites for client-side RPC-with-TLS support | expand

Commit Message

Chuck Lever III July 22, 2022, 5:25 p.m. UTC
Signed-off-by: Chuck Lever <chuck.lever@oracle.com>
---
 include/trace/events/sunrpc.h |   18 ++++++++++++++++++
 net/sunrpc/xprtsock.c         |    6 ++++--
 2 files changed, 22 insertions(+), 2 deletions(-)

Comments

Trond Myklebust July 22, 2022, 5:59 p.m. UTC | #1
On Fri, 2022-07-22 at 13:25 -0400, Chuck Lever wrote:
> Signed-off-by: Chuck Lever <chuck.lever@oracle.com>
> ---
>  include/trace/events/sunrpc.h |   18 ++++++++++++++++++
>  net/sunrpc/xprtsock.c         |    6 ++++--
>  2 files changed, 22 insertions(+), 2 deletions(-)
> 
> diff --git a/include/trace/events/sunrpc.h
> b/include/trace/events/sunrpc.h
> index b61d9c90fa26..04b6903b6c0c 100644
> --- a/include/trace/events/sunrpc.h
> +++ b/include/trace/events/sunrpc.h
> @@ -1266,6 +1266,24 @@ TRACE_EVENT(xprt_reserve,
>         )
>  );
>  
> +TRACE_EVENT(xs_data_ready,
> +       TP_PROTO(
> +               const struct rpc_xprt *xprt
> +       ),
> +
> +       TP_ARGS(xprt),
> +
> +       TP_STRUCT__entry(
> +               __sockaddr(addr, xprt->addrlen)
> +       ),
> +
> +       TP_fast_assign(
> +               __assign_sockaddr(addr, &xprt->addr, xprt->addrlen);
> +       ),
> +
> +       TP_printk("peer=%pISpc", __get_sockaddr(addr))

NACK. Please resolve and store the string up front instead of storing
the sockaddr. Most versions of perf can't resolve those kernel-specific
%p printks and just end up barfing on them.

> +);
> +
>  TRACE_EVENT(xs_stream_read_data,
>         TP_PROTO(struct rpc_xprt *xprt, ssize_t err, size_t total),
>  
> diff --git a/net/sunrpc/xprtsock.c b/net/sunrpc/xprtsock.c
> index fcdd0fca408e..eba1be9984f8 100644
> --- a/net/sunrpc/xprtsock.c
> +++ b/net/sunrpc/xprtsock.c
> @@ -1378,7 +1378,7 @@ static void xs_udp_data_receive_workfn(struct
> work_struct *work)
>  }
>  
>  /**
> - * xs_data_ready - "data ready" callback for UDP sockets
> + * xs_data_ready - "data ready" callback for sockets
>   * @sk: socket with data to read
>   *
>   */
> @@ -1386,11 +1386,13 @@ static void xs_data_ready(struct sock *sk)
>  {
>         struct rpc_xprt *xprt;
>  
> -       dprintk("RPC:       xs_data_ready...\n");
>         xprt = xprt_from_sock(sk);
>         if (xprt != NULL) {
>                 struct sock_xprt *transport = container_of(xprt,
>                                 struct sock_xprt, xprt);
> +
> +               trace_xs_data_ready(xprt);
> +
>                 transport->old_data_ready(sk);
>                 /* Any data means we had a useful conversation, so
>                  * then we don't need to delay the next reconnect
> 
>
Chuck Lever III July 22, 2022, 6:45 p.m. UTC | #2
> On Jul 22, 2022, at 1:59 PM, Trond Myklebust <trondmy@hammerspace.com> wrote:
> 
> On Fri, 2022-07-22 at 13:25 -0400, Chuck Lever wrote:
>> Signed-off-by: Chuck Lever <chuck.lever@oracle.com>
>> ---
>> include/trace/events/sunrpc.h |  18 ++++++++++++++++++
>> net/sunrpc/xprtsock.c  |  6 ++++--
>> 2 files changed, 22 insertions(+), 2 deletions(-)
>> 
>> diff --git a/include/trace/events/sunrpc.h
>> b/include/trace/events/sunrpc.h
>> index b61d9c90fa26..04b6903b6c0c 100644
>> --- a/include/trace/events/sunrpc.h
>> +++ b/include/trace/events/sunrpc.h
>> @@ -1266,6 +1266,24 @@ TRACE_EVENT(xprt_reserve,
>> )
>> );
>> 
>> +TRACE_EVENT(xs_data_ready,
>> +  TP_PROTO(
>> +  const struct rpc_xprt *xprt
>> +  ),
>> +
>> +  TP_ARGS(xprt),
>> +
>> +  TP_STRUCT__entry(
>> +  __sockaddr(addr, xprt->addrlen)
>> +  ),
>> +
>> +  TP_fast_assign(
>> +  __assign_sockaddr(addr, &xprt->addr, xprt->addrlen);
>> +  ),
>> +
>> +  TP_printk("peer=%pISpc", __get_sockaddr(addr))
> 
> NACK. Please resolve and store the string up front instead of storing
> the sockaddr. Most versions of perf can't resolve those kernel-specific
> %p printks and just end up barfing on them.

Interesting. We added get_sockaddr() to avoid this issue in
trace-cmd. Sounds like perf needs to be fixed up too, or
maybe this is another case of having an old libtraceevent?

Meanwhile, I can revert this back to the old way of handling
presentation addresses.


>> +);
>> +
>> TRACE_EVENT(xs_stream_read_data,
>> TP_PROTO(struct rpc_xprt *xprt, ssize_t err, size_t total),
>> 
>> diff --git a/net/sunrpc/xprtsock.c b/net/sunrpc/xprtsock.c
>> index fcdd0fca408e..eba1be9984f8 100644
>> --- a/net/sunrpc/xprtsock.c
>> +++ b/net/sunrpc/xprtsock.c
>> @@ -1378,7 +1378,7 @@ static void xs_udp_data_receive_workfn(struct
>> work_struct *work)
>> }
>> 
>> /**
>> - * xs_data_ready - "data ready" callback for UDP sockets
>> + * xs_data_ready - "data ready" callback for sockets
>> * @sk: socket with data to read
>> *
>> */
>> @@ -1386,11 +1386,13 @@ static void xs_data_ready(struct sock *sk)
>> {
>> struct rpc_xprt *xprt;
>> 
>> -  dprintk("RPC:  xs_data_ready...\n");
>> xprt = xprt_from_sock(sk);
>> if (xprt != NULL) {
>> struct sock_xprt *transport = container_of(xprt,
>> struct sock_xprt, xprt);
>> +
>> +  trace_xs_data_ready(xprt);
>> +
>> transport->old_data_ready(sk);
>> /* Any data means we had a useful conversation, so
>> * then we don't need to delay the next reconnect
>> 
>> 
> 
> -- 
> Trond Myklebust
> Linux NFS client maintainer, Hammerspace
> trond.myklebust@hammerspace.com

--
Chuck Lever
Steven Rostedt July 22, 2022, 8:22 p.m. UTC | #3
[ Added the user space perf folks ]

On Fri, 22 Jul 2022 18:45:30 +0000
Chuck Lever III <chuck.lever@oracle.com> wrote:

> >> +TRACE_EVENT(xs_data_ready,
> >> +  TP_PROTO(
> >> +  const struct rpc_xprt *xprt
> >> +  ),
> >> +
> >> +  TP_ARGS(xprt),
> >> +
> >> +  TP_STRUCT__entry(
> >> +  __sockaddr(addr, xprt->addrlen)
> >> +  ),
> >> +
> >> +  TP_fast_assign(
> >> +  __assign_sockaddr(addr, &xprt->addr, xprt->addrlen);
> >> +  ),
> >> +
> >> +  TP_printk("peer=%pISpc", __get_sockaddr(addr))  
> > 
> > NACK. Please resolve and store the string up front instead of storing
> > the sockaddr. Most versions of perf can't resolve those kernel-specific
> > %p printks and just end up barfing on them.  
> 
> Interesting. We added get_sockaddr() to avoid this issue in
> trace-cmd. Sounds like perf needs to be fixed up too, or
> maybe this is another case of having an old libtraceevent?
> 
> Meanwhile, I can revert this back to the old way of handling
> presentation addresses.
> 

Hmm, I thought that perf now uses the external libtraceevent.

Perhaps it hasn't been updated to the latest release that has the ability
to parse this.

Maybe just install

  git://git.kernel.org/pub/scm/libs/libtrace/libtraceevent.git

?

-- Steve
Arnaldo Carvalho de Melo July 25, 2022, 3:49 p.m. UTC | #4
Em Fri, Jul 22, 2022 at 04:22:12PM -0400, Steven Rostedt escreveu:
> [ Added the user space perf folks ]
> 
> On Fri, 22 Jul 2022 18:45:30 +0000
> Chuck Lever III <chuck.lever@oracle.com> wrote:
> 
> > >> +TRACE_EVENT(xs_data_ready,
> > >> +  TP_PROTO(
> > >> +  const struct rpc_xprt *xprt
> > >> +  ),
> > >> +
> > >> +  TP_ARGS(xprt),
> > >> +
> > >> +  TP_STRUCT__entry(
> > >> +  __sockaddr(addr, xprt->addrlen)
> > >> +  ),
> > >> +
> > >> +  TP_fast_assign(
> > >> +  __assign_sockaddr(addr, &xprt->addr, xprt->addrlen);
> > >> +  ),
> > >> +
> > >> +  TP_printk("peer=%pISpc", __get_sockaddr(addr))  
> > > 
> > > NACK. Please resolve and store the string up front instead of storing
> > > the sockaddr. Most versions of perf can't resolve those kernel-specific
> > > %p printks and just end up barfing on them.  
> > 
> > Interesting. We added get_sockaddr() to avoid this issue in
> > trace-cmd. Sounds like perf needs to be fixed up too, or
> > maybe this is another case of having an old libtraceevent?
> > 
> > Meanwhile, I can revert this back to the old way of handling
> > presentation addresses.
> > 
> 
> Hmm, I thought that perf now uses the external libtraceevent.
> 
> Perhaps it hasn't been updated to the latest release that has the ability
> to parse this.
> 
> Maybe just install
> 
>   git://git.kernel.org/pub/scm/libs/libtrace/libtraceevent.git

To use it one has to use:

  make -C tools/perf LIBTRACEEVENT_DYNAMIC=1

Then we get it linked with libtraceevent-devel:

$ ldd ~/bin/perf | grep traceevent
	libtraceevent.so.1 => /lib64/libtraceevent.so.1 (0x00007faa50f93000)
$

Perhaps it'd be better to check if libtracevent-devel is installed and
use it, falling back to tools/lib/traceevent/ and then adding a warning
that the in-tree codebase is being used?

- Arnaldo
Steven Rostedt July 25, 2022, 4:06 p.m. UTC | #5
On Mon, 25 Jul 2022 12:49:20 -0300
Arnaldo Carvalho de Melo <acme@kernel.org> wrote:

> Perhaps it'd be better to check if libtracevent-devel is installed and
> use it, falling back to tools/lib/traceevent/ and then adding a warning
> that the in-tree codebase is being used?

Yeah, this is the way trace-cmd went. For a few releases, it would just
warn that it couldn't find the system libraries, and then fall back to the
internals, and then it finally just removed the internals and failed with a
message stating where to get the necessary libraries.

-- Steve
diff mbox series

Patch

diff --git a/include/trace/events/sunrpc.h b/include/trace/events/sunrpc.h
index b61d9c90fa26..04b6903b6c0c 100644
--- a/include/trace/events/sunrpc.h
+++ b/include/trace/events/sunrpc.h
@@ -1266,6 +1266,24 @@  TRACE_EVENT(xprt_reserve,
 	)
 );
 
+TRACE_EVENT(xs_data_ready,
+	TP_PROTO(
+		const struct rpc_xprt *xprt
+	),
+
+	TP_ARGS(xprt),
+
+	TP_STRUCT__entry(
+		__sockaddr(addr, xprt->addrlen)
+	),
+
+	TP_fast_assign(
+		__assign_sockaddr(addr, &xprt->addr, xprt->addrlen);
+	),
+
+	TP_printk("peer=%pISpc", __get_sockaddr(addr))
+);
+
 TRACE_EVENT(xs_stream_read_data,
 	TP_PROTO(struct rpc_xprt *xprt, ssize_t err, size_t total),
 
diff --git a/net/sunrpc/xprtsock.c b/net/sunrpc/xprtsock.c
index fcdd0fca408e..eba1be9984f8 100644
--- a/net/sunrpc/xprtsock.c
+++ b/net/sunrpc/xprtsock.c
@@ -1378,7 +1378,7 @@  static void xs_udp_data_receive_workfn(struct work_struct *work)
 }
 
 /**
- * xs_data_ready - "data ready" callback for UDP sockets
+ * xs_data_ready - "data ready" callback for sockets
  * @sk: socket with data to read
  *
  */
@@ -1386,11 +1386,13 @@  static void xs_data_ready(struct sock *sk)
 {
 	struct rpc_xprt *xprt;
 
-	dprintk("RPC:       xs_data_ready...\n");
 	xprt = xprt_from_sock(sk);
 	if (xprt != NULL) {
 		struct sock_xprt *transport = container_of(xprt,
 				struct sock_xprt, xprt);
+
+		trace_xs_data_ready(xprt);
+
 		transport->old_data_ready(sk);
 		/* Any data means we had a useful conversation, so
 		 * then we don't need to delay the next reconnect