[PATCH v2 0/2] sunrpc: allow dprintk() to go to the trace buffer instead of console

[PATCH v2 0/2] sunrpc: allow dprintk() to go to the trace buffer instead of console

[Jeff Layton]

While we have added a lot of static tracepoints in the last few years,
we still have a load of dprintks in place at all levels of the
NFS/NLM/RPC stack. At the same time, they're pretty useless under any
significant load due to the console overhead.

This adds a new Kconfig switch to allow those to go to the trace buffer
instead. In addition to being more efficient, that allows us to enable
static tracepoints alongside dprintk() and get a unified log.

Signed-off-by: Jeff Layton <jlayton@kernel.org>
---
Changes in v2:
- pr_default() doesn't exist. Use printk(KERN_DEFAULT ...) instead.
- Link to v1: https://lore.kernel.org/r/20250821-nfs-testing-v1-0-f06099963eda@kernel.org

---
Jeff Layton (2):
      sunrpc: remove dfprintk_cont() and dfprintk_rcu_cont()
      sunrpc: add a Kconfig option to redirect dfprintk() output to trace buffer

 fs/nfs/write.c               |  6 +++---
 include/linux/sunrpc/debug.h | 30 ++++++++----------------------
 net/sunrpc/Kconfig           | 14 ++++++++++++++
 3 files changed, 25 insertions(+), 25 deletions(-)
---
base-commit: 80a1bea0cd81de70c56b37a8292c23d57419776f
change-id: 20250821-nfs-testing-2b21070952d4

Best regards,
-- 
Jeff Layton <jlayton@kernel.org>

[PATCH v2 1/2] sunrpc: remove dfprintk_cont() and dfprintk_rcu_cont()

[Jeff Layton]

KERN_CONT hails from a simpler time, when SMP wasn't the norm. These
days, it doesn't quite work right since another printk() can always race
in between the first one and the one being "continued".

Nothing calls dprintk_rcu_cont(), so just remove it. The only caller of
dprintk_cont() is in nfs_commit_release_pages(). Just use a normal
dprintk() there instead, since this is not SMP-safe anyway.

Signed-off-by: Jeff Layton <jlayton@kernel.org>
---
 fs/nfs/write.c               |  6 +++---
 include/linux/sunrpc/debug.h | 24 ++----------------------
 2 files changed, 5 insertions(+), 25 deletions(-)

diff --git a/fs/nfs/write.c b/fs/nfs/write.c
index d881486d235ba042feedd2dd59d6a60b366b9600..4d5699b4a1fabff39e67998af40561620b532db6 100644
--- a/fs/nfs/write.c
+++ b/fs/nfs/write.c
@@ -1862,7 +1862,7 @@ static void nfs_commit_release_pages(struct nfs_commit_data *data)
 				nfs_mapping_set_error(folio, status);
 				nfs_inode_remove_request(req);
 			}
-			dprintk_cont(", error = %d\n", status);
+			dprintk(", error = %d\n", status);
 			goto next;
 		}
 
@@ -1872,11 +1872,11 @@ static void nfs_commit_release_pages(struct nfs_commit_data *data)
 			/* We have a match */
 			if (folio)
 				nfs_inode_remove_request(req);
-			dprintk_cont(" OK\n");
+			dprintk(" OK\n");
 			goto next;
 		}
 		/* We have a mismatch. Write the page again */
-		dprintk_cont(" mismatch\n");
+		dprintk(" mismatch\n");
 		nfs_mark_request_dirty(req);
 		atomic_long_inc(&NFS_I(data->inode)->redirtied_pages);
 	next:
diff --git a/include/linux/sunrpc/debug.h b/include/linux/sunrpc/debug.h
index f6aeed07fe04e3d51d7f9d23b10fe86d36241b45..99a6fa4a1d6af0b275546a53957f07c9a509f2ac 100644
--- a/include/linux/sunrpc/debug.h
+++ b/include/linux/sunrpc/debug.h
@@ -23,12 +23,8 @@ extern unsigned int		nlm_debug;
 
 #define dprintk(fmt, ...)						\
 	dfprintk(FACILITY, fmt, ##__VA_ARGS__)
-#define dprintk_cont(fmt, ...)						\
-	dfprintk_cont(FACILITY, fmt, ##__VA_ARGS__)
 #define dprintk_rcu(fmt, ...)						\
 	dfprintk_rcu(FACILITY, fmt, ##__VA_ARGS__)
-#define dprintk_rcu_cont(fmt, ...)					\
-	dfprintk_rcu_cont(FACILITY, fmt, ##__VA_ARGS__)
 
 #undef ifdebug
 #if IS_ENABLED(CONFIG_SUNRPC_DEBUG)
@@ -37,29 +33,14 @@ extern unsigned int		nlm_debug;
 # define dfprintk(fac, fmt, ...)					\
 do {									\
 	ifdebug(fac)							\
-		printk(KERN_DEFAULT fmt, ##__VA_ARGS__);		\
-} while (0)
-
-# define dfprintk_cont(fac, fmt, ...)					\
-do {									\
-	ifdebug(fac)							\
-		printk(KERN_CONT fmt, ##__VA_ARGS__);			\
+		printk(KERN_DEFAULT fmt, ##__VA_ARGS__);				\
 } while (0)
 
 # define dfprintk_rcu(fac, fmt, ...)					\
 do {									\
 	ifdebug(fac) {							\
 		rcu_read_lock();					\
-		printk(KERN_DEFAULT fmt, ##__VA_ARGS__);		\
-		rcu_read_unlock();					\
-	}								\
-} while (0)
-
-# define dfprintk_rcu_cont(fac, fmt, ...)				\
-do {									\
-	ifdebug(fac) {							\
-		rcu_read_lock();					\
-		printk(KERN_CONT fmt, ##__VA_ARGS__);			\
+		printk(KERN_DEFAULT fmt, ##__VA_ARGS__);				\
 		rcu_read_unlock();					\
 	}								\
 } while (0)
@@ -68,7 +49,6 @@ do {									\
 #else
 # define ifdebug(fac)		if (0)
 # define dfprintk(fac, fmt, ...)	do {} while (0)
-# define dfprintk_cont(fac, fmt, ...)	do {} while (0)
 # define dfprintk_rcu(fac, fmt, ...)	do {} while (0)
 # define RPC_IFDEBUG(x)
 #endif

-- 
2.50.1

[PATCH v2 2/2] sunrpc: add a Kconfig option to redirect dfprintk() output to trace buffer

[Jeff Layton]

We have a lot of old dprintk() call sites that aren't going anywhere
anytime soon. At the same time, turning them up is a serious burden on
the host due to the console locking overhead.

Add a new Kconfig option that redirects dfprintk() output to the trace
buffer. This is more efficient than logging to the console and allows
for proper interleaving of dprintk and static tracepoint events.

Since using trace_printk() causes scary warnings to pop at boot time,
this new option defaults to "n".

Signed-off-by: Jeff Layton <jlayton@kernel.org>
---
 include/linux/sunrpc/debug.h | 10 ++++++++--
 net/sunrpc/Kconfig           | 14 ++++++++++++++
 2 files changed, 22 insertions(+), 2 deletions(-)

diff --git a/include/linux/sunrpc/debug.h b/include/linux/sunrpc/debug.h
index 99a6fa4a1d6af0b275546a53957f07c9a509f2ac..891f6173c951a6644018237017c845d81b42aa76 100644
--- a/include/linux/sunrpc/debug.h
+++ b/include/linux/sunrpc/debug.h
@@ -30,17 +30,23 @@ extern unsigned int		nlm_debug;
 #if IS_ENABLED(CONFIG_SUNRPC_DEBUG)
 # define ifdebug(fac)		if (unlikely(rpc_debug & RPCDBG_##fac))
 
+# if IS_ENABLED(CONFIG_SUNRPC_DEBUG_TRACE)
+#  define __sunrpc_printk(fmt, ...)	trace_printk(fmt, ##__VA_ARGS__)
+# else
+#  define __sunrpc_printk(fmt, ...)	printk(KERN_DEFAULT fmt, ##__VA_ARGS__)
+# endif
+
 # define dfprintk(fac, fmt, ...)					\
 do {									\
 	ifdebug(fac)							\
-		printk(KERN_DEFAULT fmt, ##__VA_ARGS__);				\
+		__sunrpc_printk(fmt, ##__VA_ARGS__);			\
 } while (0)
 
 # define dfprintk_rcu(fac, fmt, ...)					\
 do {									\
 	ifdebug(fac) {							\
 		rcu_read_lock();					\
-		printk(KERN_DEFAULT fmt, ##__VA_ARGS__);				\
+		__sunrpc_printk(fmt, ##__VA_ARGS__);			\
 		rcu_read_unlock();					\
 	}								\
 } while (0)
diff --git a/net/sunrpc/Kconfig b/net/sunrpc/Kconfig
index 2d8b67dac7b5b58a8a86c3022dd573746fb22547..a570e7adf270fb8976f751266bbffe39ef696c6a 100644
--- a/net/sunrpc/Kconfig
+++ b/net/sunrpc/Kconfig
@@ -101,6 +101,20 @@ config SUNRPC_DEBUG
 
 	  If unsure, say Y.
 
+config SUNRPC_DEBUG_TRACE
+	bool "RPC: Send dfprintk() output to the trace buffer"
+	depends on SUNRPC_DEBUG && TRACING
+	default n
+	help
+          dprintk() output can be voluminous, which can overwhelm the
+          kernel's logging facility as it must be sent to the console.
+          This option causes dprintk() output to go to the trace buffer
+          instead of the kernel log.
+
+          This will cause warnings about trace_printk() being used to be
+          logged at boot time, so say N unless you are debugging a problem
+          with sunrpc-based clients or services.
+
 config SUNRPC_XPRT_RDMA
 	tristate "RPC-over-RDMA transport"
 	depends on SUNRPC && INFINIBAND && INFINIBAND_ADDR_TRANS

-- 
2.50.1

Re: [PATCH v2 1/2] sunrpc: remove dfprintk_cont() and dfprintk_rcu_cont()

[Simon Horman]

On Fri, Aug 22, 2025 at 09:19:22AM -0400, Jeff Layton wrote:
> KERN_CONT hails from a simpler time, when SMP wasn't the norm. These
> days, it doesn't quite work right since another printk() can always race
> in between the first one and the one being "continued".
> 
> Nothing calls dprintk_rcu_cont(), so just remove it. The only caller of
> dprintk_cont() is in nfs_commit_release_pages(). Just use a normal
> dprintk() there instead, since this is not SMP-safe anyway.
> 
> Signed-off-by: Jeff Layton <jlayton@kernel.org>

Reviewed-by: Simon Horman <horms@kernel.org>

Re: [PATCH v2 2/2] sunrpc: add a Kconfig option to redirect dfprintk() output to trace buffer

[Simon Horman]

On Fri, Aug 22, 2025 at 09:19:23AM -0400, Jeff Layton wrote:
> We have a lot of old dprintk() call sites that aren't going anywhere
> anytime soon. At the same time, turning them up is a serious burden on
> the host due to the console locking overhead.
> 
> Add a new Kconfig option that redirects dfprintk() output to the trace
> buffer. This is more efficient than logging to the console and allows
> for proper interleaving of dprintk and static tracepoint events.
> 
> Since using trace_printk() causes scary warnings to pop at boot time,
> this new option defaults to "n".
> 
> Signed-off-by: Jeff Layton <jlayton@kernel.org>

Reviewed-by: Simon Horman <horms@kernel.org>

Re: [PATCH v2 1/2] sunrpc: remove dfprintk_cont() and dfprintk_rcu_cont()

[Chuck Lever]

On 8/22/25 9:19 AM, Jeff Layton wrote:
> KERN_CONT hails from a simpler time, when SMP wasn't the norm. These
> days, it doesn't quite work right since another printk() can always race
> in between the first one and the one being "continued".
> 
> Nothing calls dprintk_rcu_cont(), so just remove it. The only caller of
> dprintk_cont() is in nfs_commit_release_pages(). Just use a normal
> dprintk() there instead, since this is not SMP-safe anyway.
> 
> Signed-off-by: Jeff Layton <jlayton@kernel.org>
> ---
>  fs/nfs/write.c               |  6 +++---
>  include/linux/sunrpc/debug.h | 24 ++----------------------
>  2 files changed, 5 insertions(+), 25 deletions(-)
> 
> diff --git a/fs/nfs/write.c b/fs/nfs/write.c
> index d881486d235ba042feedd2dd59d6a60b366b9600..4d5699b4a1fabff39e67998af40561620b532db6 100644
> --- a/fs/nfs/write.c
> +++ b/fs/nfs/write.c
> @@ -1862,7 +1862,7 @@ static void nfs_commit_release_pages(struct nfs_commit_data *data)
>  				nfs_mapping_set_error(folio, status);
>  				nfs_inode_remove_request(req);
>  			}
> -			dprintk_cont(", error = %d\n", status);
> +			dprintk(", error = %d\n", status);
>  			goto next;
>  		}
>  
> @@ -1872,11 +1872,11 @@ static void nfs_commit_release_pages(struct nfs_commit_data *data)
>  			/* We have a match */
>  			if (folio)
>  				nfs_inode_remove_request(req);
> -			dprintk_cont(" OK\n");
> +			dprintk(" OK\n");
>  			goto next;
>  		}
>  		/* We have a mismatch. Write the page again */
> -		dprintk_cont(" mismatch\n");
> +		dprintk(" mismatch\n");
>  		nfs_mark_request_dirty(req);
>  		atomic_long_inc(&NFS_I(data->inode)->redirtied_pages);
>  	next:
> diff --git a/include/linux/sunrpc/debug.h b/include/linux/sunrpc/debug.h
> index f6aeed07fe04e3d51d7f9d23b10fe86d36241b45..99a6fa4a1d6af0b275546a53957f07c9a509f2ac 100644
> --- a/include/linux/sunrpc/debug.h
> +++ b/include/linux/sunrpc/debug.h
> @@ -23,12 +23,8 @@ extern unsigned int		nlm_debug;
>  
>  #define dprintk(fmt, ...)						\
>  	dfprintk(FACILITY, fmt, ##__VA_ARGS__)
> -#define dprintk_cont(fmt, ...)						\
> -	dfprintk_cont(FACILITY, fmt, ##__VA_ARGS__)
>  #define dprintk_rcu(fmt, ...)						\
>  	dfprintk_rcu(FACILITY, fmt, ##__VA_ARGS__)
> -#define dprintk_rcu_cont(fmt, ...)					\
> -	dfprintk_rcu_cont(FACILITY, fmt, ##__VA_ARGS__)
>  
>  #undef ifdebug
>  #if IS_ENABLED(CONFIG_SUNRPC_DEBUG)
> @@ -37,29 +33,14 @@ extern unsigned int		nlm_debug;
>  # define dfprintk(fac, fmt, ...)					\
>  do {									\
>  	ifdebug(fac)							\
> -		printk(KERN_DEFAULT fmt, ##__VA_ARGS__);		\
> -} while (0)
> -
> -# define dfprintk_cont(fac, fmt, ...)					\
> -do {									\
> -	ifdebug(fac)							\
> -		printk(KERN_CONT fmt, ##__VA_ARGS__);			\
> +		printk(KERN_DEFAULT fmt, ##__VA_ARGS__);				\
>  } while (0)
>  
>  # define dfprintk_rcu(fac, fmt, ...)					\
>  do {									\
>  	ifdebug(fac) {							\
>  		rcu_read_lock();					\
> -		printk(KERN_DEFAULT fmt, ##__VA_ARGS__);		\
> -		rcu_read_unlock();					\
> -	}								\
> -} while (0)
> -
> -# define dfprintk_rcu_cont(fac, fmt, ...)				\
> -do {									\
> -	ifdebug(fac) {							\
> -		rcu_read_lock();					\
> -		printk(KERN_CONT fmt, ##__VA_ARGS__);			\
> +		printk(KERN_DEFAULT fmt, ##__VA_ARGS__);				\
>  		rcu_read_unlock();					\
>  	}								\
>  } while (0)
> @@ -68,7 +49,6 @@ do {									\
>  #else
>  # define ifdebug(fac)		if (0)
>  # define dfprintk(fac, fmt, ...)	do {} while (0)
> -# define dfprintk_cont(fac, fmt, ...)	do {} while (0)
>  # define dfprintk_rcu(fac, fmt, ...)	do {} while (0)
>  # define RPC_IFDEBUG(x)
>  #endif
> 

Reviewed-by: Chuck Lever <chuck.lever@oracle.com>

-- 
Chuck Lever

Re: [PATCH v2 2/2] sunrpc: add a Kconfig option to redirect dfprintk() output to trace buffer

[Chuck Lever]

On 8/22/25 9:19 AM, Jeff Layton wrote:
> We have a lot of old dprintk() call sites that aren't going anywhere
> anytime soon. At the same time, turning them up is a serious burden on
> the host due to the console locking overhead.
> 
> Add a new Kconfig option that redirects dfprintk() output to the trace
> buffer. This is more efficient than logging to the console and allows
> for proper interleaving of dprintk and static tracepoint events.
> 
> Since using trace_printk() causes scary warnings to pop at boot time,
> this new option defaults to "n".
> 
> Signed-off-by: Jeff Layton <jlayton@kernel.org>
> ---
>  include/linux/sunrpc/debug.h | 10 ++++++++--
>  net/sunrpc/Kconfig           | 14 ++++++++++++++
>  2 files changed, 22 insertions(+), 2 deletions(-)
> 
> diff --git a/include/linux/sunrpc/debug.h b/include/linux/sunrpc/debug.h
> index 99a6fa4a1d6af0b275546a53957f07c9a509f2ac..891f6173c951a6644018237017c845d81b42aa76 100644
> --- a/include/linux/sunrpc/debug.h
> +++ b/include/linux/sunrpc/debug.h
> @@ -30,17 +30,23 @@ extern unsigned int		nlm_debug;
>  #if IS_ENABLED(CONFIG_SUNRPC_DEBUG)
>  # define ifdebug(fac)		if (unlikely(rpc_debug & RPCDBG_##fac))
>  
> +# if IS_ENABLED(CONFIG_SUNRPC_DEBUG_TRACE)
> +#  define __sunrpc_printk(fmt, ...)	trace_printk(fmt, ##__VA_ARGS__)
> +# else
> +#  define __sunrpc_printk(fmt, ...)	printk(KERN_DEFAULT fmt, ##__VA_ARGS__)
> +# endif
> +
>  # define dfprintk(fac, fmt, ...)					\
>  do {									\
>  	ifdebug(fac)							\
> -		printk(KERN_DEFAULT fmt, ##__VA_ARGS__);				\
> +		__sunrpc_printk(fmt, ##__VA_ARGS__);			\
>  } while (0)
>  
>  # define dfprintk_rcu(fac, fmt, ...)					\
>  do {									\
>  	ifdebug(fac) {							\
>  		rcu_read_lock();					\
> -		printk(KERN_DEFAULT fmt, ##__VA_ARGS__);				\
> +		__sunrpc_printk(fmt, ##__VA_ARGS__);			\
>  		rcu_read_unlock();					\
>  	}								\
>  } while (0)
> diff --git a/net/sunrpc/Kconfig b/net/sunrpc/Kconfig
> index 2d8b67dac7b5b58a8a86c3022dd573746fb22547..a570e7adf270fb8976f751266bbffe39ef696c6a 100644
> --- a/net/sunrpc/Kconfig
> +++ b/net/sunrpc/Kconfig
> @@ -101,6 +101,20 @@ config SUNRPC_DEBUG
>  
>  	  If unsure, say Y.
>  
> +config SUNRPC_DEBUG_TRACE
> +	bool "RPC: Send dfprintk() output to the trace buffer"
> +	depends on SUNRPC_DEBUG && TRACING
> +	default n
> +	help
> +          dprintk() output can be voluminous, which can overwhelm the
> +          kernel's logging facility as it must be sent to the console.
> +          This option causes dprintk() output to go to the trace buffer
> +          instead of the kernel log.
> +
> +          This will cause warnings about trace_printk() being used to be
> +          logged at boot time, so say N unless you are debugging a problem
> +          with sunrpc-based clients or services.
> +
>  config SUNRPC_XPRT_RDMA
>  	tristate "RPC-over-RDMA transport"
>  	depends on SUNRPC && INFINIBAND && INFINIBAND_ADDR_TRANS
> 

Nice and surgical. But I'm on the fence about whether this is a
good long-term strategy. No real objections, though.

Reviewed-by: Chuck Lever <chuck.lever@oracle.com>


-- 
Chuck Lever