[PATCH v1 0/6] Deprecate dprintk in svcrdma

[PATCH v1 0/6] Deprecate dprintk in svcrdma

[Chuck Lever]

This patch series moves forward with the removal of dprintk in
SUNRPC in favor of tracepoints. This is the last step for the
svcrdma component.

---

Chuck Lever (6):
      svcrdma: Remove dprintk() call sites in module handlers
      svcrdma: Remove dprintk call site in svc_rdma_create_xprt()
      svcrdma: Remove dprintk call site in svc_rdma_parse_connect_private()
      svcrdma: Remove dprintk call sites during QP creation
      svcrdma: Remove dprintk call sites during accept
      svcrdma: Remove include/linux/sunrpc/debug.h


 net/sunrpc/xprtrdma/svc_rdma.c           |  9 ------
 net/sunrpc/xprtrdma/svc_rdma_recvfrom.c  |  1 -
 net/sunrpc/xprtrdma/svc_rdma_sendto.c    |  1 -
 net/sunrpc/xprtrdma/svc_rdma_transport.c | 37 ++----------------------
 4 files changed, 3 insertions(+), 45 deletions(-)

--
Chuck Lever

[PATCH v1 1/6] svcrdma: Remove dprintk() call sites in module handlers

[Chuck Lever]

As part of the deprecation of dprintk, remove low-value dprintk call
sites in the module init and clean-up functions.

Signed-off-by: Chuck Lever <chuck.lever@oracle.com>
---
 net/sunrpc/xprtrdma/svc_rdma.c |    9 ---------
 1 file changed, 9 deletions(-)

diff --git a/net/sunrpc/xprtrdma/svc_rdma.c b/net/sunrpc/xprtrdma/svc_rdma.c
index 5bc20e9d09cd..2470a7926469 100644
--- a/net/sunrpc/xprtrdma/svc_rdma.c
+++ b/net/sunrpc/xprtrdma/svc_rdma.c
@@ -49,8 +49,6 @@
 #include <linux/sunrpc/sched.h>
 #include <linux/sunrpc/svc_rdma.h>
 
-#define RPCDBG_FACILITY	RPCDBG_SVCXPRT
-
 /* RPC/RDMA parameters */
 unsigned int svcrdma_ord = 16;	/* historical default */
 static unsigned int min_ord = 1;
@@ -275,7 +273,6 @@ static int svc_rdma_proc_init(void)
 
 void svc_rdma_cleanup(void)
 {
-	dprintk("SVCRDMA Module Removed, deregister RPC RDMA transport\n");
 	svc_unreg_xprt_class(&svc_rdma_class);
 	svc_rdma_proc_cleanup();
 }
@@ -284,12 +281,6 @@ int svc_rdma_init(void)
 {
 	int rc;
 
-	dprintk("SVCRDMA Module Init, register RPC RDMA transport\n");
-	dprintk("\tsvcrdma_ord      : %d\n", svcrdma_ord);
-	dprintk("\tmax_requests     : %u\n", svcrdma_max_requests);
-	dprintk("\tmax_bc_requests  : %u\n", svcrdma_max_bc_requests);
-	dprintk("\tmax_inline       : %d\n", svcrdma_max_req_size);
-
 	rc = svc_rdma_proc_init();
 	if (rc)
 		return rc;

[PATCH v1 2/6] svcrdma: Remove dprintk call site in svc_rdma_create_xprt()

[Chuck Lever]

Deprecation. Generally a dprintk() that appears during a memory
exhaustion scenario is unnecessary and can even be
counterproductive.

Signed-off-by: Chuck Lever <chuck.lever@oracle.com>
---
 net/sunrpc/xprtrdma/svc_rdma_transport.c |    5 ++---
 1 file changed, 2 insertions(+), 3 deletions(-)

diff --git a/net/sunrpc/xprtrdma/svc_rdma_transport.c b/net/sunrpc/xprtrdma/svc_rdma_transport.c
index 94b20fb47135..9aea253af2da 100644
--- a/net/sunrpc/xprtrdma/svc_rdma_transport.c
+++ b/net/sunrpc/xprtrdma/svc_rdma_transport.c
@@ -129,10 +129,9 @@ static struct svcxprt_rdma *svc_rdma_create_xprt(struct svc_serv *serv,
 {
 	struct svcxprt_rdma *cma_xprt = kzalloc(sizeof *cma_xprt, GFP_KERNEL);
 
-	if (!cma_xprt) {
-		dprintk("svcrdma: failed to create new transport\n");
+	if (!cma_xprt)
 		return NULL;
-	}
+
 	svc_xprt_init(net, &svc_rdma_class, &cma_xprt->sc_xprt, serv);
 	INIT_LIST_HEAD(&cma_xprt->sc_accept_q);
 	INIT_LIST_HEAD(&cma_xprt->sc_rq_dto_q);

[PATCH v1 3/6] svcrdma: Remove dprintk call site in svc_rdma_parse_connect_private()

[Chuck Lever]

Deprecation. The effect of the RPCRDMA_CMP_F_SND_W_INV_OK setting is
obvious from subsequent server activity.

Signed-off-by: Chuck Lever <chuck.lever@oracle.com>
---
 net/sunrpc/xprtrdma/svc_rdma_transport.c |    9 +--------
 1 file changed, 1 insertion(+), 8 deletions(-)

diff --git a/net/sunrpc/xprtrdma/svc_rdma_transport.c b/net/sunrpc/xprtrdma/svc_rdma_transport.c
index 9aea253af2da..11cecfb7761a 100644
--- a/net/sunrpc/xprtrdma/svc_rdma_transport.c
+++ b/net/sunrpc/xprtrdma/svc_rdma_transport.c
@@ -164,16 +164,9 @@ svc_rdma_parse_connect_private(struct svcxprt_rdma *newxprt,
 
 	if (pmsg &&
 	    pmsg->cp_magic == rpcrdma_cmp_magic &&
-	    pmsg->cp_version == RPCRDMA_CMP_VERSION) {
+	    pmsg->cp_version == RPCRDMA_CMP_VERSION)
 		newxprt->sc_snd_w_inv = pmsg->cp_flags &
 					RPCRDMA_CMP_F_SND_W_INV_OK;
-
-		dprintk("svcrdma: client send_size %u, recv_size %u "
-			"remote inv %ssupported\n",
-			rpcrdma_decode_buffer_size(pmsg->cp_send_size),
-			rpcrdma_decode_buffer_size(pmsg->cp_recv_size),
-			newxprt->sc_snd_w_inv ? "" : "un");
-	}
 }
 
 /*

[PATCH v1 4/6] svcrdma: Remove dprintk call sites during QP creation

[Chuck Lever]

Deprecation. Printing pointer addresses in the log isn't valuable,
and the other information is now available from the core's qp_create
tracepoint.

Signed-off-by: Chuck Lever <chuck.lever@oracle.com>
---
 net/sunrpc/xprtrdma/svc_rdma_transport.c |    7 -------
 1 file changed, 7 deletions(-)

diff --git a/net/sunrpc/xprtrdma/svc_rdma_transport.c b/net/sunrpc/xprtrdma/svc_rdma_transport.c
index 11cecfb7761a..e105e2d89b9b 100644
--- a/net/sunrpc/xprtrdma/svc_rdma_transport.c
+++ b/net/sunrpc/xprtrdma/svc_rdma_transport.c
@@ -445,13 +445,6 @@ static struct svc_xprt *svc_rdma_accept(struct svc_xprt *xprt)
 	qp_attr.qp_type = IB_QPT_RC;
 	qp_attr.send_cq = newxprt->sc_sq_cq;
 	qp_attr.recv_cq = newxprt->sc_rq_cq;
-	dprintk("svcrdma: newxprt->sc_cm_id=%p, newxprt->sc_pd=%p\n",
-		newxprt->sc_cm_id, newxprt->sc_pd);
-	dprintk("    cap.max_send_wr = %d, cap.max_recv_wr = %d\n",
-		qp_attr.cap.max_send_wr, qp_attr.cap.max_recv_wr);
-	dprintk("    cap.max_send_sge = %d, cap.max_recv_sge = %d\n",
-		qp_attr.cap.max_send_sge, qp_attr.cap.max_recv_sge);
-
 	ret = rdma_create_qp(newxprt->sc_cm_id, newxprt->sc_pd, &qp_attr);
 	if (ret) {
 		trace_svcrdma_qp_err(newxprt, ret);

[PATCH v1 5/6] svcrdma: Remove dprintk call sites during accept

[Chuck Lever]

Deprecation. Most of this information is available from other
tracepoints.

Signed-off-by: Chuck Lever <chuck.lever@oracle.com>
---
 net/sunrpc/xprtrdma/svc_rdma_transport.c |   16 ----------------
 1 file changed, 16 deletions(-)

diff --git a/net/sunrpc/xprtrdma/svc_rdma_transport.c b/net/sunrpc/xprtrdma/svc_rdma_transport.c
index e105e2d89b9b..acfde6e1594c 100644
--- a/net/sunrpc/xprtrdma/svc_rdma_transport.c
+++ b/net/sunrpc/xprtrdma/svc_rdma_transport.c
@@ -54,14 +54,12 @@
 #include <rdma/rw.h>
 
 #include <linux/sunrpc/addr.h>
-#include <linux/sunrpc/debug.h>
 #include <linux/sunrpc/svc_xprt.h>
 #include <linux/sunrpc/svc_rdma.h>
 
 #include "xprt_rdma.h"
 #include <trace/events/rpcrdma.h>
 
-#define RPCDBG_FACILITY	RPCDBG_SVCXPRT
 
 static struct svcxprt_rdma *svc_rdma_create_xprt(struct svc_serv *serv,
 						 struct net *net);
@@ -365,7 +363,6 @@ static struct svc_xprt *svc_rdma_accept(struct svc_xprt *xprt)
 	unsigned int ctxts, rq_depth;
 	struct ib_device *dev;
 	int ret = 0;
-	RPC_IFDEBUG(struct sockaddr *sap);
 
 	listen_rdma = container_of(xprt, struct svcxprt_rdma, sc_xprt);
 	clear_bit(XPT_CONN, &xprt->xpt_flags);
@@ -492,19 +489,6 @@ static struct svc_xprt *svc_rdma_accept(struct svc_xprt *xprt)
 		goto errout;
 	}
 
-#if IS_ENABLED(CONFIG_SUNRPC_DEBUG)
-	dprintk("svcrdma: new connection %p accepted:\n", newxprt);
-	sap = (struct sockaddr *)&newxprt->sc_cm_id->route.addr.src_addr;
-	dprintk("    local address   : %pIS:%u\n", sap, rpc_get_port(sap));
-	sap = (struct sockaddr *)&newxprt->sc_cm_id->route.addr.dst_addr;
-	dprintk("    remote address  : %pIS:%u\n", sap, rpc_get_port(sap));
-	dprintk("    max_sge         : %d\n", newxprt->sc_max_send_sges);
-	dprintk("    sq_depth        : %d\n", newxprt->sc_sq_depth);
-	dprintk("    rdma_rw_ctxs    : %d\n", ctxts);
-	dprintk("    max_requests    : %d\n", newxprt->sc_max_requests);
-	dprintk("    ord             : %d\n", conn_param.initiator_depth);
-#endif
-
 	return &newxprt->sc_xprt;
 
  errout:

[PATCH v1 6/6] svcrdma: Remove include/linux/sunrpc/debug.h

[Chuck Lever]

Deprecation. svcrdma no longer uses dprintk.

Signed-off-by: Chuck Lever <chuck.lever@oracle.com>
---
 net/sunrpc/xprtrdma/svc_rdma_recvfrom.c |    1 -
 net/sunrpc/xprtrdma/svc_rdma_sendto.c   |    1 -
 2 files changed, 2 deletions(-)

diff --git a/net/sunrpc/xprtrdma/svc_rdma_recvfrom.c b/net/sunrpc/xprtrdma/svc_rdma_recvfrom.c
index cf76a6ad127b..3be39fc5cec4 100644
--- a/net/sunrpc/xprtrdma/svc_rdma_recvfrom.c
+++ b/net/sunrpc/xprtrdma/svc_rdma_recvfrom.c
@@ -99,7 +99,6 @@
 #include <rdma/rdma_cm.h>
 
 #include <linux/sunrpc/xdr.h>
-#include <linux/sunrpc/debug.h>
 #include <linux/sunrpc/rpc_rdma.h>
 #include <linux/sunrpc/svc_rdma.h>
 
diff --git a/net/sunrpc/xprtrdma/svc_rdma_sendto.c b/net/sunrpc/xprtrdma/svc_rdma_sendto.c
index 22a871e6fe4d..e973e5b3ce08 100644
--- a/net/sunrpc/xprtrdma/svc_rdma_sendto.c
+++ b/net/sunrpc/xprtrdma/svc_rdma_sendto.c
@@ -105,7 +105,6 @@
 #include <rdma/ib_verbs.h>
 #include <rdma/rdma_cm.h>
 
-#include <linux/sunrpc/debug.h>
 #include <linux/sunrpc/svc_rdma.h>
 
 #include "xprt_rdma.h"

Re: [PATCH v1 0/6] Deprecate dprintk in svcrdma

[J. Bruce Fields]

On Wed, Oct 13, 2021 at 10:46:49AM -0400, Chuck Lever wrote:
> This patch series moves forward with the removal of dprintk in
> SUNRPC in favor of tracepoints. This is the last step for the
> svcrdma component.

Makes sense to me.

I would like some (very short) documentation, somewhere.  Partly just
for my sake!  I'm not sure exactly what to recommend to bug reporters.

I guess 

	trace-cmd record -e 'sunrpc:*
	trace-cmd report

would be a rough substitute for "rpcdebug -m rpc -s all"?

Do we have a couple examples of issues that could be diagnosed with
tracepoints?  In the past I don't feel like I've ended up using dprintks
all that much; somehow they're not usually where I need them.  But maybe
that's just me.  And maybe as we put more thought into where tracepoints
should be, they'll get more useful.

Documentation/filesystems/nfs/, or the linux-nfs wiki, could be easy
places to put it.  Though *something* in the man pages would be nice.
At a minimum, a warning in rpcdebug(8) that we're gradually phasing out
dprintks.

--b.

> 
> ---
> 
> Chuck Lever (6):
>       svcrdma: Remove dprintk() call sites in module handlers
>       svcrdma: Remove dprintk call site in svc_rdma_create_xprt()
>       svcrdma: Remove dprintk call site in svc_rdma_parse_connect_private()
>       svcrdma: Remove dprintk call sites during QP creation
>       svcrdma: Remove dprintk call sites during accept
>       svcrdma: Remove include/linux/sunrpc/debug.h
> 
> 
>  net/sunrpc/xprtrdma/svc_rdma.c           |  9 ------
>  net/sunrpc/xprtrdma/svc_rdma_recvfrom.c  |  1 -
>  net/sunrpc/xprtrdma/svc_rdma_sendto.c    |  1 -
>  net/sunrpc/xprtrdma/svc_rdma_transport.c | 37 ++----------------------
>  4 files changed, 3 insertions(+), 45 deletions(-)
> 
> --
> Chuck Lever

Re: [PATCH v1 0/6] Deprecate dprintk in svcrdma

[Chuck Lever III]

> On Oct 13, 2021, at 11:59 AM, J. Bruce Fields <bfields@fieldses.org> wrote:
> 
> On Wed, Oct 13, 2021 at 10:46:49AM -0400, Chuck Lever wrote:
>> This patch series moves forward with the removal of dprintk in
>> SUNRPC in favor of tracepoints. This is the last step for the
>> svcrdma component.
> 
> Makes sense to me.
> 
> I would like some (very short) documentation, somewhere.  Partly just
> for my sake!  I'm not sure exactly what to recommend to bug reporters.
> 
> I guess 
> 
> 	trace-cmd record -e 'sunrpc:*'
> 	trace-cmd report
> 
> would be a rough substitute for "rpcdebug -m rpc -s all"?

It would, but tracepoints can be enabled one event
at a time. If you're looking for a direct replacement
for a specific rpcdebug invocation, it might be better
to examine the current sunrpc debug facilities and
provide specific command lines to mimic those.

"rpcdebug -vh" gives us:

rpc        xprt call debug nfs auth bind sched trans svcsock svcdsp misc cache all
nfs        vfs dircache lookupcache pagecache proc xdr file root callback client mount fscache pnfs pnfs_ld state all
nfsd       sock fh export svc proc fileop auth repcache xdr lockd all
nlm        svc client clntlock svclock monitor clntsubs svcsubs hostcache xdr all


If tracepoints are named carefully, we can provide
specific command lines to enable them as groups. So,
for instance, I was thinking rpcdebug might display:

	trace-cmd list | grep svcrdma

to list tracepoints related to server side RDMA, or:

	trace-cmd list | grep svcsock

to show tracepoints related to server side sockets.
Then:

	trace-cmd record -e sunrpc:svcsock\*

enables just the socket-related trace events, which
coincidentally happens to line up with:

	rpcdebug -m rpc -s svcsock


> Do we have a couple examples of issues that could be diagnosed with
> tracepoints?

Anything you can do with dprintk you can do with trace
points. Plus because tracepoints are lower overhead, they
can be enabled and used in production environments,
unlike dprintk.

Also, tracepoints can trigger specific user space actions
when they fire. You could for example set up a tracepoint
in the RPC client that fires when a retransmit timeout
occurs, and it could trigger a script to start tcpdump.


> In the past I don't feel like I've ended up using dprintks
> all that much; somehow they're not usually where I need them.  But maybe
> that's just me.  And maybe as we put more thought into where tracepoints
> should be, they'll get more useful.

> Documentation/filesystems/nfs/, or the linux-nfs wiki, could be easy
> places to put it.  Though *something* in the man pages would be nice.
> At a minimum, a warning in rpcdebug(8) that we're gradually phasing out
> dprintks.

As I understood the conversation last week, SteveD and
DaveW volunteered to be responsible for changes to
rpcdebug?

So far we haven't had much documentation for dprintk. That
means we are starting more or less from scratch for
explaining observability in the NFS stacks. Free rein, and
all that.

--
Chuck Lever

Re: [PATCH v1 0/6] Deprecate dprintk in svcrdma

[David Wysochanski]

On Wed, Oct 13, 2021 at 12:50 PM Chuck Lever III <chuck.lever@oracle.com> wrote:
>
>
>
> > On Oct 13, 2021, at 11:59 AM, J. Bruce Fields <bfields@fieldses.org> wrote:
> >
> > On Wed, Oct 13, 2021 at 10:46:49AM -0400, Chuck Lever wrote:
> >> This patch series moves forward with the removal of dprintk in
> >> SUNRPC in favor of tracepoints. This is the last step for the
> >> svcrdma component.
> >
> > Makes sense to me.
> >
> > I would like some (very short) documentation, somewhere.  Partly just
> > for my sake!  I'm not sure exactly what to recommend to bug reporters.
> >
> > I guess
> >
> >       trace-cmd record -e 'sunrpc:*'
> >       trace-cmd report
> >
> > would be a rough substitute for "rpcdebug -m rpc -s all"?
>
> It would, but tracepoints can be enabled one event
> at a time. If you're looking for a direct replacement
> for a specific rpcdebug invocation, it might be better
> to examine the current sunrpc debug facilities and
> provide specific command lines to mimic those.
>
> "rpcdebug -vh" gives us:
>
> rpc        xprt call debug nfs auth bind sched trans svcsock svcdsp misc cache all
> nfs        vfs dircache lookupcache pagecache proc xdr file root callback client mount fscache pnfs pnfs_ld state all
> nfsd       sock fh export svc proc fileop auth repcache xdr lockd all
> nlm        svc client clntlock svclock monitor clntsubs svcsubs hostcache xdr all
>
>
> If tracepoints are named carefully, we can provide
> specific command lines to enable them as groups. So,
> for instance, I was thinking rpcdebug might display:
>
>         trace-cmd list | grep svcrdma
>
> to list tracepoints related to server side RDMA, or:
>
>         trace-cmd list | grep svcsock
>
> to show tracepoints related to server side sockets.
> Then:
>
>         trace-cmd record -e sunrpc:svcsock\*
>
> enables just the socket-related trace events, which
> coincidentally happens to line up with:
>
>         rpcdebug -m rpc -s svcsock
>
>
> > Do we have a couple examples of issues that could be diagnosed with
> > tracepoints?
>
> Anything you can do with dprintk you can do with trace
> points. Plus because tracepoints are lower overhead, they
> can be enabled and used in production environments,
> unlike dprintk.
>
> Also, tracepoints can trigger specific user space actions
> when they fire. You could for example set up a tracepoint
> in the RPC client that fires when a retransmit timeout
> occurs, and it could trigger a script to start tcpdump.
>
>
> > In the past I don't feel like I've ended up using dprintks
> > all that much; somehow they're not usually where I need them.  But maybe
> > that's just me.  And maybe as we put more thought into where tracepoints
> > should be, they'll get more useful.
>
> > Documentation/filesystems/nfs/, or the linux-nfs wiki, could be easy
> > places to put it.  Though *something* in the man pages would be nice.
> > At a minimum, a warning in rpcdebug(8) that we're gradually phasing out
> > dprintks.
>
> As I understood the conversation last week, SteveD and
> DaveW volunteered to be responsible for changes to
> rpcdebug?
>

Well I don't remember it exactly like that, but it's probably close.

I made a suggestion for the last kernel patch that deprecates any
rpcdebug facility, to leave one dfprintk in, stating there is no
information in the kernel anymore for this facility, so not to expect
this rpcdebug flag to produce any meaningful debug output, and
possibly redirect to ftrace facilities.  I brought that idea up
because of my fscache patches which totally removed the last dfprintk
in NFS fscache, and I wasn't sure what the deprecation procedure
was.  As I recall you didn't like that idea as it was never done before
with other rpcdebug flag deprecations, and it was shot down.

I suppose we could put the same type of userspace patch to rpcdebug
that looks for kernel versions and prints a message if someone tries
to use a deprecated flag?  Would that be better?


> So far we haven't had much documentation for dprintk. That
> means we are starting more or less from scratch for
> explaining observability in the NFS stacks. Free rein, and
> all that.
>
> --
> Chuck Lever
>
>
>

Re: [PATCH v1 0/6] Deprecate dprintk in svcrdma

[Chuck Lever III]

> On Oct 13, 2021, at 2:35 PM, David Wysochanski <dwysocha@redhat.com> wrote:
> 
> On Wed, Oct 13, 2021 at 12:50 PM Chuck Lever III <chuck.lever@oracle.com> wrote:
>> 
>> 
>> 
>>> On Oct 13, 2021, at 11:59 AM, J. Bruce Fields <bfields@fieldses.org> wrote:
>>> 
>>> On Wed, Oct 13, 2021 at 10:46:49AM -0400, Chuck Lever wrote:
>>>> This patch series moves forward with the removal of dprintk in
>>>> SUNRPC in favor of tracepoints. This is the last step for the
>>>> svcrdma component.
>>> 
>>> Makes sense to me.
>>> 
>>> I would like some (very short) documentation, somewhere.  Partly just
>>> for my sake!  I'm not sure exactly what to recommend to bug reporters.
>>> 
>>> I guess
>>> 
>>>      trace-cmd record -e 'sunrpc:*'
>>>      trace-cmd report
>>> 
>>> would be a rough substitute for "rpcdebug -m rpc -s all"?
>> 
>> It would, but tracepoints can be enabled one event
>> at a time. If you're looking for a direct replacement
>> for a specific rpcdebug invocation, it might be better
>> to examine the current sunrpc debug facilities and
>> provide specific command lines to mimic those.
>> 
>> "rpcdebug -vh" gives us:
>> 
>> rpc        xprt call debug nfs auth bind sched trans svcsock svcdsp misc cache all
>> nfs        vfs dircache lookupcache pagecache proc xdr file root callback client mount fscache pnfs pnfs_ld state all
>> nfsd       sock fh export svc proc fileop auth repcache xdr lockd all
>> nlm        svc client clntlock svclock monitor clntsubs svcsubs hostcache xdr all
>> 
>> 
>> If tracepoints are named carefully, we can provide
>> specific command lines to enable them as groups. So,
>> for instance, I was thinking rpcdebug might display:
>> 
>>        trace-cmd list | grep svcrdma
>> 
>> to list tracepoints related to server side RDMA, or:
>> 
>>        trace-cmd list | grep svcsock
>> 
>> to show tracepoints related to server side sockets.
>> Then:
>> 
>>        trace-cmd record -e sunrpc:svcsock\*
>> 
>> enables just the socket-related trace events, which
>> coincidentally happens to line up with:
>> 
>>        rpcdebug -m rpc -s svcsock
>> 
>> 
>>> Do we have a couple examples of issues that could be diagnosed with
>>> tracepoints?
>> 
>> Anything you can do with dprintk you can do with trace
>> points. Plus because tracepoints are lower overhead, they
>> can be enabled and used in production environments,
>> unlike dprintk.
>> 
>> Also, tracepoints can trigger specific user space actions
>> when they fire. You could for example set up a tracepoint
>> in the RPC client that fires when a retransmit timeout
>> occurs, and it could trigger a script to start tcpdump.
>> 
>> 
>>> In the past I don't feel like I've ended up using dprintks
>>> all that much; somehow they're not usually where I need them.  But maybe
>>> that's just me.  And maybe as we put more thought into where tracepoints
>>> should be, they'll get more useful.
>> 
>>> Documentation/filesystems/nfs/, or the linux-nfs wiki, could be easy
>>> places to put it.  Though *something* in the man pages would be nice.
>>> At a minimum, a warning in rpcdebug(8) that we're gradually phasing out
>>> dprintks.
>> 
>> As I understood the conversation last week, SteveD and
>> DaveW volunteered to be responsible for changes to
>> rpcdebug?
>> 
> 
> Well I don't remember it exactly like that, but it's probably close.
> 
> I made a suggestion for the last kernel patch that deprecates any
> rpcdebug facility, to leave one dfprintk in, stating there is no
> information in the kernel anymore for this facility, so not to expect
> this rpcdebug flag to produce any meaningful debug output, and
> possibly redirect to ftrace facilities.  I brought that idea up
> because of my fscache patches which totally removed the last dfprintk
> in NFS fscache, and I wasn't sure what the deprecation procedure
> was.  As I recall you didn't like that idea as it was never done before
> with other rpcdebug flag deprecations, and it was shot down.
> 
> I suppose we could put the same type of userspace patch to rpcdebug
> that looks for kernel versions and prints a message if someone tries
> to use a deprecated flag?  Would that be better?

I don't recall discussing leaving one dprintk in place for
each facility. My impression is that changing rpcdebug in
this manner is what was decided during that conversation.


>> So far we haven't had much documentation for dprintk. That
>> means we are starting more or less from scratch for
>> explaining observability in the NFS stacks. Free rein, and
>> all that.
>> 
>> --
>> Chuck Lever

--
Chuck Lever

Re: [PATCH v1 0/6] Deprecate dprintk in svcrdma

[David Wysochanski]

On Wed, Oct 13, 2021 at 5:03 PM Chuck Lever III <chuck.lever@oracle.com> wrote:
>
>
>
> > On Oct 13, 2021, at 2:35 PM, David Wysochanski <dwysocha@redhat.com> wrote:
> >
> > On Wed, Oct 13, 2021 at 12:50 PM Chuck Lever III <chuck.lever@oracle.com> wrote:
> >>
> >>
> >>
> >>> On Oct 13, 2021, at 11:59 AM, J. Bruce Fields <bfields@fieldses.org> wrote:
> >>>
> >>> On Wed, Oct 13, 2021 at 10:46:49AM -0400, Chuck Lever wrote:
> >>>> This patch series moves forward with the removal of dprintk in
> >>>> SUNRPC in favor of tracepoints. This is the last step for the
> >>>> svcrdma component.
> >>>
> >>> Makes sense to me.
> >>>
> >>> I would like some (very short) documentation, somewhere.  Partly just
> >>> for my sake!  I'm not sure exactly what to recommend to bug reporters.
> >>>
> >>> I guess
> >>>
> >>>      trace-cmd record -e 'sunrpc:*'
> >>>      trace-cmd report
> >>>
> >>> would be a rough substitute for "rpcdebug -m rpc -s all"?
> >>
> >> It would, but tracepoints can be enabled one event
> >> at a time. If you're looking for a direct replacement
> >> for a specific rpcdebug invocation, it might be better
> >> to examine the current sunrpc debug facilities and
> >> provide specific command lines to mimic those.
> >>
> >> "rpcdebug -vh" gives us:
> >>
> >> rpc        xprt call debug nfs auth bind sched trans svcsock svcdsp misc cache all
> >> nfs        vfs dircache lookupcache pagecache proc xdr file root callback client mount fscache pnfs pnfs_ld state all
> >> nfsd       sock fh export svc proc fileop auth repcache xdr lockd all
> >> nlm        svc client clntlock svclock monitor clntsubs svcsubs hostcache xdr all
> >>
> >>
> >> If tracepoints are named carefully, we can provide
> >> specific command lines to enable them as groups. So,
> >> for instance, I was thinking rpcdebug might display:
> >>
> >>        trace-cmd list | grep svcrdma
> >>
> >> to list tracepoints related to server side RDMA, or:
> >>
> >>        trace-cmd list | grep svcsock
> >>
> >> to show tracepoints related to server side sockets.
> >> Then:
> >>
> >>        trace-cmd record -e sunrpc:svcsock\*
> >>
> >> enables just the socket-related trace events, which
> >> coincidentally happens to line up with:
> >>
> >>        rpcdebug -m rpc -s svcsock
> >>
> >>
> >>> Do we have a couple examples of issues that could be diagnosed with
> >>> tracepoints?
> >>
> >> Anything you can do with dprintk you can do with trace
> >> points. Plus because tracepoints are lower overhead, they
> >> can be enabled and used in production environments,
> >> unlike dprintk.
> >>
> >> Also, tracepoints can trigger specific user space actions
> >> when they fire. You could for example set up a tracepoint
> >> in the RPC client that fires when a retransmit timeout
> >> occurs, and it could trigger a script to start tcpdump.
> >>
> >>
> >>> In the past I don't feel like I've ended up using dprintks
> >>> all that much; somehow they're not usually where I need them.  But maybe
> >>> that's just me.  And maybe as we put more thought into where tracepoints
> >>> should be, they'll get more useful.
> >>
> >>> Documentation/filesystems/nfs/, or the linux-nfs wiki, could be easy
> >>> places to put it.  Though *something* in the man pages would be nice.
> >>> At a minimum, a warning in rpcdebug(8) that we're gradually phasing out
> >>> dprintks.
> >>
> >> As I understood the conversation last week, SteveD and
> >> DaveW volunteered to be responsible for changes to
> >> rpcdebug?
> >>
> >
> > Well I don't remember it exactly like that, but it's probably close.
> >
> > I made a suggestion for the last kernel patch that deprecates any
> > rpcdebug facility, to leave one dfprintk in, stating there is no
> > information in the kernel anymore for this facility, so not to expect
> > this rpcdebug flag to produce any meaningful debug output, and
> > possibly redirect to ftrace facilities.  I brought that idea up
> > because of my fscache patches which totally removed the last dfprintk
> > in NFS fscache, and I wasn't sure what the deprecation procedure
> > was.  As I recall you didn't like that idea as it was never done before
> > with other rpcdebug flag deprecations, and it was shot down.
> >
> > I suppose we could put the same type of userspace patch to rpcdebug
> > that looks for kernel versions and prints a message if someone tries
> > to use a deprecated flag?  Would that be better?
>
> I don't recall discussing leaving one dprintk in place for
> each facility. My impression is that changing rpcdebug in
> this manner is what was decided during that conversation.
>

Just to follow up on this since I think this was an action item more
appropriate for me.
FYI, I have spoken to a couple Red Hat support engineers and asked
them to work on:
1. man page update for rpcdebug
2. rpcdebug warning if a flag is enabled on a kernel that does not
produce any output

They are making good progress and I hope they will post something to
the list within week or two.



>
> >> So far we haven't had much documentation for dprintk. That
> >> means we are starting more or less from scratch for
> >> explaining observability in the NFS stacks. Free rein, and
> >> all that.
> >>
> >> --
> >> Chuck Lever
>
> --
> Chuck Lever
>
>
>