usbatm: printk_ratelimit() always called in the atm_rldbg()

usbatm: printk_ratelimit() always called in the atm_rldbg()

[Krzysztof Mazur]

Hi,

commit 2d6401cf4ca3861692a4779745e0049cac769d10
("USB: usbatm: move the atm_dbg() call to use dynamic debug")
changed the atm_rldbg() to:

#define atm_rldbg(instance, format, arg...)		\
	if (printk_ratelimit())				\
		atm_dbg(instance , format , ## arg)

and now printk_ratelimit() is always called even when debugging is
disabled and a lot of "callbacks suppressed" messages are printed
by the printk_ratelimit():

[...]
usbatm_rx_process: 4977 callbacks suppressed
usbatm_extract_one_cell: 2920 callbacks suppressed
[...]


I'm not sure how to fix that, maybe we need dynamic_pr_debug_ratelimit()?

Krzysiek

Re: usbatm: printk_ratelimit() always called in the atm_rldbg()

[Greg Kroah-Hartman]

On Sat, Oct 26, 2013 at 03:29:56PM +0200, Krzysztof Mazur wrote:
> Hi,
> 
> commit 2d6401cf4ca3861692a4779745e0049cac769d10
> ("USB: usbatm: move the atm_dbg() call to use dynamic debug")
> changed the atm_rldbg() to:
> 
> #define atm_rldbg(instance, format, arg...)		\
> 	if (printk_ratelimit())				\
> 		atm_dbg(instance , format , ## arg)
> 
> and now printk_ratelimit() is always called even when debugging is
> disabled and a lot of "callbacks suppressed" messages are printed
> by the printk_ratelimit():
> 
> [...]
> usbatm_rx_process: 4977 callbacks suppressed
> usbatm_extract_one_cell: 2920 callbacks suppressed
> [...]
> 
> 
> I'm not sure how to fix that, maybe we need dynamic_pr_debug_ratelimit()?

How about just deleting the use of that macro entirely?  Odds are it's
not really needed anymore, right?

thanks,

greg k-h

[PATCH] printk: pr_debug_ratelimited: check state first to reduce "callbacks suppressed" messages

[Joe Perches]

pr_debug_ratelimited should be coded similar to dev_dbg_ratelimited
to reduce the "callbacks suppressed" messages.

Signed-off-by: Joe Perches <joe@perches.com>
---
On Sat, 2013-10-26 at 18:37 +0100, Greg Kroah-Hartman wrote:
> On Sat, Oct 26, 2013 at 03:29:56PM +0200, Krzysztof Mazur wrote:
> > Hi,
> > 
> > commit 2d6401cf4ca3861692a4779745e0049cac769d10
> > ("USB: usbatm: move the atm_dbg() call to use dynamic debug")
> > changed the atm_rldbg() to:
> > 
> > #define atm_rldbg(instance, format, arg...)		\
> > 	if (printk_ratelimit())				\
> > 		atm_dbg(instance , format , ## arg)
> > 
> > and now printk_ratelimit() is always called even when debugging is
> > disabled and a lot of "callbacks suppressed" messages are printed
> > by the printk_ratelimit():
> > 
> > [...]
> > usbatm_rx_process: 4977 callbacks suppressed
> > usbatm_extract_one_cell: 2920 callbacks suppressed
> > [...]
> > 
> > 
> > I'm not sure how to fix that, maybe we need dynamic_pr_debug_ratelimit()?
> 
> How about just deleting the use of that macro entirely?  Odds are it's
> not really needed anymore, right?

 include/linux/printk.h | 14 +++++++++++++-
 1 file changed, 13 insertions(+), 1 deletion(-)

diff --git a/include/linux/printk.h b/include/linux/printk.h
index e6131a78..449d924 100644
--- a/include/linux/printk.h
+++ b/include/linux/printk.h
@@ -343,7 +343,19 @@ extern asmlinkage void dump_stack(void) __cold;
 #endif
 
 /* If you are writing a driver, please use dev_dbg instead */
-#if defined(DEBUG)
+#if defined(CONFIG_DYNAMIC_DEBUG)
+/* descriptor check is first to prevent flooding with "callbacks suppressed" */
+#define pr_debug_ratelimited(dev, fmt, ...)				\
+do {									\
+	static DEFINE_RATELIMIT_STATE(_rs,				\
+				      DEFAULT_RATELIMIT_INTERVAL,	\
+				      DEFAULT_RATELIMIT_BURST);		\
+	DEFINE_DYNAMIC_DEBUG_METADATA(descriptor, fmt);			\
+	if (unlikely(descriptor.flags & _DPRINTK_FLAGS_PRINT) &&	\
+	    __ratelimit(&_rs))						\
+		__dynamic_pr_debug(fmt, ##__VA_ARGS__);			\
+} while (0)
+#elif defined(DEBUG)
 #define pr_debug_ratelimited(fmt, ...)					\
 	printk_ratelimited(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__)
 #else

Re: [PATCH] printk: pr_debug_ratelimited: check state first to reduce "callbacks suppressed" messages

[Greg Kroah-Hartman]

On Sat, Oct 26, 2013 at 11:52:02AM -0700, Joe Perches wrote:
> pr_debug_ratelimited should be coded similar to dev_dbg_ratelimited
> to reduce the "callbacks suppressed" messages.
> 
> Signed-off-by: Joe Perches <joe@perches.com>

Looks good, I'll queue both of these up soon.

greg k-h

Re: [PATCH] printk: pr_debug_ratelimited: check state first to reduce "callbacks suppressed" messages

[Joe Perches]

On Sat, 2013-10-26 at 20:01 +0100, Greg Kroah-Hartman wrote:
> On Sat, Oct 26, 2013 at 11:52:02AM -0700, Joe Perches wrote:
> > pr_debug_ratelimited should be coded similar to dev_dbg_ratelimited
> > to reduce the "callbacks suppressed" messages.
> > Signed-off-by: Joe Perches <joe@perches.com>
> Looks good, I'll queue both of these up soon.

Sorry Greg, hand out the brown paper bag please.

Just ignore these both, I'll resubmit properly tested ones.

[PATCH V2] printk: pr_debug_ratelimited: check state first to reduce "callbacks suppressed" messages

[Joe Perches]

pr_debug_ratelimited should be coded similarly to dev_dbg_ratelimited
to reduce the "callbacks suppressed" messages.

Add #include <linux/dynamic_debug.h> to printk.h. Unfortunately, this
new #include must be after the prototype/declaration of function printk.

It may be better to split out these _ratelimited declarations into
a separate file one day.

Any use of these pr_<foo>_ratelimited functions must also have another
specific #include <ratelimited.h>.  Most users have this done indirectly
via #include <linux/kernel.h>

printk.h may not #include <linux/ratelimit.h> as it causes circular
dependencies and compilation failures.

Signed-off-by: Joe Perches <joe@perches.com>
---
V2: Fix #include dependencies and typos.

Compile tested with and without CONFIG_DYNAMIC_DEBUG

It looks to me as if device.h should also have #include <dynamic_debug.h>
It currently gets the #include indirectly via kobject.h -> kernel.h.

 include/linux/printk.h | 16 +++++++++++++++-
 1 file changed, 15 insertions(+), 1 deletion(-)

diff --git a/include/linux/printk.h b/include/linux/printk.h
index e6131a78..6949258 100644
--- a/include/linux/printk.h
+++ b/include/linux/printk.h
@@ -233,6 +233,8 @@ extern asmlinkage void dump_stack(void) __cold;
 	no_printk(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__)
 #endif
 
+#include <linux/dynamic_debug.h>
+
 /* If you are writing a driver, please use dev_dbg instead */
 #if defined(CONFIG_DYNAMIC_DEBUG)
 /* dynamic_pr_debug() uses pr_fmt() internally so we don't need it here */
@@ -343,7 +345,19 @@ extern asmlinkage void dump_stack(void) __cold;
 #endif
 
 /* If you are writing a driver, please use dev_dbg instead */
-#if defined(DEBUG)
+#if defined(CONFIG_DYNAMIC_DEBUG)
+/* descriptor check is first to prevent flooding with "callbacks suppressed" */
+#define pr_debug_ratelimited(fmt, ...)					\
+do {									\
+	static DEFINE_RATELIMIT_STATE(_rs,				\
+				      DEFAULT_RATELIMIT_INTERVAL,	\
+				      DEFAULT_RATELIMIT_BURST);		\
+	DEFINE_DYNAMIC_DEBUG_METADATA(descriptor, fmt);			\
+	if (unlikely(descriptor.flags & _DPRINTK_FLAGS_PRINT) &&	\
+	    __ratelimit(&_rs))						\
+		__dynamic_pr_debug(&descriptor, fmt, ##__VA_ARGS__);	\
+} while (0)
+#elif defined(DEBUG)
 #define pr_debug_ratelimited(fmt, ...)					\
 	printk_ratelimited(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__)
 #else

Re: [PATCH V2] printk: pr_debug_ratelimited: check state first to reduce "callbacks suppressed" messages

[Krzysztof Mazur]

On Sat, Oct 26, 2013 at 08:41:53PM -0700, Joe Perches wrote:
> pr_debug_ratelimited should be coded similarly to dev_dbg_ratelimited
> to reduce the "callbacks suppressed" messages.
> 
> Add #include <linux/dynamic_debug.h> to printk.h. Unfortunately, this
> new #include must be after the prototype/declaration of function printk.
> 
> It may be better to split out these _ratelimited declarations into
> a separate file one day.
> 
> Any use of these pr_<foo>_ratelimited functions must also have another
> specific #include <ratelimited.h>.  Most users have this done indirectly
> via #include <linux/kernel.h>
> 
> printk.h may not #include <linux/ratelimit.h> as it causes circular
> dependencies and compilation failures.
> 
> Signed-off-by: Joe Perches <joe@perches.com>
> ---
> V2: Fix #include dependencies and typos.
> 
> Compile tested with and without CONFIG_DYNAMIC_DEBUG

I've tested both patches without CONFIG_DYNAMIC_DEBUG and
with enabled and disabled debugging with CONFIG_DYNAMIC_DEBUG
and everything seems work correctly.

Thanks,
Krzysiek

[PATCH] atmusb: Fix dynamic_debug macros

[Joe Perches]

Fix use of atm_dbg to all normal pr_debug not dynamic_pr_debug
because dynamic_pr_debug may not be compiled in at all.

Signed-off-by: Joe Perches <joe@perches.com>
---
 drivers/usb/atm/usbatm.h | 13 ++++++-------
 1 file changed, 6 insertions(+), 7 deletions(-)

diff --git a/drivers/usb/atm/usbatm.h b/drivers/usb/atm/usbatm.h
index 5651231..2104b4b 100644
--- a/drivers/usb/atm/usbatm.h
+++ b/drivers/usb/atm/usbatm.h
@@ -59,13 +59,12 @@
 	atm_printk(KERN_INFO, instance , format , ## arg)
 #define atm_warn(instance, format, arg...)	\
 	atm_printk(KERN_WARNING, instance , format , ## arg)
-#define atm_dbg(instance, format, arg...)		\
-	dynamic_pr_debug("ATM dev %d: " format ,	\
-	(instance)->atm_dev->number , ## arg)
-#define atm_rldbg(instance, format, arg...)		\
-	if (printk_ratelimit())				\
-		atm_dbg(instance , format , ## arg)
-
+#define atm_dbg(instance, format, arg...)				\
+	pr_debug("ATM dev %d: " format,					\
+		 (instance)->atm_dev->number, ##__VA_ARGS__)
+#define atm_rldbg(instance, format, arg...)				\
+	pr_debug_ratelimited("ATM dev %d: " format,			\
+			     (instance)->atm_dev->number, ##__VA_ARGS__)
 
 /* flags, set by mini-driver in bind() */
 

Re: [PATCH] atmusb: Fix dynamic_debug macros

[Joe Perches]

On Sat, 2013-10-26 at 11:55 -0700, Joe Perches wrote:
> Fix use of atm_dbg to all normal pr_debug not dynamic_pr_debug
> because dynamic_pr_debug may not be compiled in at all.

Greg, please don't apply this one.
I'll resubmit one that actually works.

(the arg...) should be ...

> +#define atm_dbg(instance, format, arg...)				\
                                     ^ oops.

> +#define atm_rldbg(instance, format, arg...)				\
> +	pr_debug_ratelimited("ATM dev %d: " format,			\
> +			     (instance)->atm_dev->number, ##__VA_ARGS__)

here too.

Re: [PATCH] atmusb: Fix dynamic_debug macros

[Krzysztof Mazur]

On Sat, Oct 26, 2013 at 12:28:56PM -0700, Joe Perches wrote:
> On Sat, 2013-10-26 at 11:55 -0700, Joe Perches wrote:
> > Fix use of atm_dbg to all normal pr_debug not dynamic_pr_debug
> > because dynamic_pr_debug may not be compiled in at all.
> 
> Greg, please don't apply this one.
> I'll resubmit one that actually works.
> 
> (the arg...) should be ...
> 
> > +#define atm_dbg(instance, format, arg...)				\
>                                      ^ oops.
> 
> > +#define atm_rldbg(instance, format, arg...)				\
> > +	pr_debug_ratelimited("ATM dev %d: " format,			\
> > +			     (instance)->atm_dev->number, ##__VA_ARGS__)
> 
> here too.
> 

Yeah, I initially fixed that with changing "##__VAR_ARGS" to "## arg",
but without with "arg..." -> "..." it also compiles and runs correctly.

I tested that only in my configuration - without DEBUG and DYNAMIC_DEBUG
- and compile tested that it with DYNAMIC_DEBUG. If you like you can add:

Tested-by: Krzysztof Mazur <krzysiek@podlesie.net>

BTW: the driver is named usbatm, not atmusb.

Thanks,
Krzysiek

[PATCH V2] usbatm: Fix dynamic_debug / ratelimited atm_dbg and atm_rldbg macros

[Joe Perches]

Fix atm_dbg to use normal pr_debug not dynamic_pr_debug
because dynamic_pr_debug may not be compiled in at all.

Signed-off-by: Joe Perches <joe@perches.com>
---
V2: Fix macro use of arg... vs ... typo
    Fix usbatm vs atmusb typo (thanks Krzysiek)

 drivers/usb/atm/usbatm.h | 14 +++++++-------
 1 file changed, 7 insertions(+), 7 deletions(-)

diff --git a/drivers/usb/atm/usbatm.h b/drivers/usb/atm/usbatm.h
index 5651231..f3eecd9 100644
--- a/drivers/usb/atm/usbatm.h
+++ b/drivers/usb/atm/usbatm.h
@@ -34,6 +34,7 @@
 #include <linux/stringify.h>
 #include <linux/usb.h>
 #include <linux/mutex.h>
+#include <linux/ratelimit.h>
 
 /*
 #define VERBOSE_DEBUG
@@ -59,13 +60,12 @@
 	atm_printk(KERN_INFO, instance , format , ## arg)
 #define atm_warn(instance, format, arg...)	\
 	atm_printk(KERN_WARNING, instance , format , ## arg)
-#define atm_dbg(instance, format, arg...)		\
-	dynamic_pr_debug("ATM dev %d: " format ,	\
-	(instance)->atm_dev->number , ## arg)
-#define atm_rldbg(instance, format, arg...)		\
-	if (printk_ratelimit())				\
-		atm_dbg(instance , format , ## arg)
-
+#define atm_dbg(instance, format, ...)					\
+	pr_debug("ATM dev %d: " format,					\
+		 (instance)->atm_dev->number, ##__VA_ARGS__)
+#define atm_rldbg(instance, format, ...)				\
+	pr_debug_ratelimited("ATM dev %d: " format,			\
+			     (instance)->atm_dev->number, ##__VA_ARGS__)
 
 /* flags, set by mini-driver in bind() */