2013-10-26 13:30:02

by Krzysztof Mazur

[permalink] [raw]
Subject: usbatm: printk_ratelimit() always called in the atm_rldbg()

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


2013-10-26 17:35:49

by Greg Kroah-Hartman

[permalink] [raw]
Subject: Re: usbatm: printk_ratelimit() always called in the atm_rldbg()

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

2013-10-26 18:52:09

by Joe Perches

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

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

Signed-off-by: Joe Perches <[email protected]>
---
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

2013-10-26 18:55:34

by Joe Perches

[permalink] [raw]
Subject: [PATCH] atmusb: Fix dynamic_debug macros

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 <[email protected]>
---
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() */


2013-10-26 19:00:10

by Greg Kroah-Hartman

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

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

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

greg k-h

2013-10-26 19:29:25

by Joe Perches

[permalink] [raw]
Subject: Re: [PATCH] atmusb: Fix dynamic_debug macros

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.

2013-10-26 19:51:25

by Joe Perches

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

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 <[email protected]>
> 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.

2013-10-26 20:02:42

by Krzysztof Mazur

[permalink] [raw]
Subject: Re: [PATCH] atmusb: Fix dynamic_debug macros

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

BTW: the driver is named usbatm, not atmusb.

Thanks,
Krzysiek

2013-10-27 03:42:03

by Joe Perches

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

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

2013-10-27 03:49:29

by Joe Perches

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

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 <[email protected]>
---
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() */



2013-10-27 10:33:47

by Krzysztof Mazur

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

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