[PATCH 1/1] driver-core: Shut up dev_dbg_reatelimited() without DEBUG

[PATCH 1/1] driver-core: Shut up dev_dbg_reatelimited() without DEBUG

[Hiroshi Doyu]

dev_dbg_reatelimited() without DEBUG printed "217078 callbacks
suppressed". This shouldn't print anything without DEBUG.

Signed-off-by: Hiroshi Doyu <hdoyu-DDmLM1+adcrQT0dZR+AlfA@public.gmane.org>
Reported-by: Antti Palosaari <crope-X3B1VOXEql0@public.gmane.org>
---
 include/linux/device.h |    6 +++++-
 1 files changed, 5 insertions(+), 1 deletions(-)

diff --git a/include/linux/device.h b/include/linux/device.h
index eb945e1..d4dc26e 100644
--- a/include/linux/device.h
+++ b/include/linux/device.h
@@ -962,9 +962,13 @@ do {									\
 	dev_level_ratelimited(dev_notice, dev, fmt, ##__VA_ARGS__)
 #define dev_info_ratelimited(dev, fmt, ...)				\
 	dev_level_ratelimited(dev_info, dev, fmt, ##__VA_ARGS__)
+#if defined(DEBUG)
 #define dev_dbg_ratelimited(dev, fmt, ...)				\
 	dev_level_ratelimited(dev_dbg, dev, fmt, ##__VA_ARGS__)
-
+#else
+#define dev_dbg_ratelimited(dev, fmt, ...)			\
+	no_printk(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__)
+#endif
 /*
  * Stupid hackaround for existing uses of non-printk uses dev_info
  *
-- 
1.7.5.4

Re: [PATCH 1/1] driver-core: Shut up dev_dbg_reatelimited() without DEBUG

[Antti Palosaari]

On 08/17/2012 09:04 AM, Hiroshi Doyu wrote:
> dev_dbg_reatelimited() without DEBUG printed "217078 callbacks
> suppressed". This shouldn't print anything without DEBUG.
>
> Signed-off-by: Hiroshi Doyu <hdoyu-DDmLM1+adcrQT0dZR+AlfA@public.gmane.org>
> Reported-by: Antti Palosaari <crope-X3B1VOXEql0@public.gmane.org>
> ---
>   include/linux/device.h |    6 +++++-
>   1 files changed, 5 insertions(+), 1 deletions(-)
>
> diff --git a/include/linux/device.h b/include/linux/device.h
> index eb945e1..d4dc26e 100644
> --- a/include/linux/device.h
> +++ b/include/linux/device.h
> @@ -962,9 +962,13 @@ do {									\
>   	dev_level_ratelimited(dev_notice, dev, fmt, ##__VA_ARGS__)
>   #define dev_info_ratelimited(dev, fmt, ...)				\
>   	dev_level_ratelimited(dev_info, dev, fmt, ##__VA_ARGS__)
> +#if defined(DEBUG)
>   #define dev_dbg_ratelimited(dev, fmt, ...)				\
>   	dev_level_ratelimited(dev_dbg, dev, fmt, ##__VA_ARGS__)
> -
> +#else
> +#define dev_dbg_ratelimited(dev, fmt, ...)			\
> +	no_printk(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__)
> +#endif
>   /*
>    * Stupid hackaround for existing uses of non-printk uses dev_info
>    *
>

NACK. I don't think that's correct behavior. After that patch it kills 
all output of dev_dbg_ratelimited(). If I use dynamic debugs and order 
debugs, I expect to see debugs as earlier.

I did test module in order to demonstrate problem. Here it is:
http://git.linuxtv.org/anttip/media_tree.git/shortlog/refs/heads/dev_dbg_ratelimited

There is also file named: test_results.txt
It contains 4 test cases:
1) without that patch & without module dynamic debug
2) without that patch & module dynamic debug ordered
3) with that patch & without module dynamic debug
4) with that patch & module dynamic debug ordered

regards
Antti

-- 
http://palosaari.fi/

Re: [PATCH 1/1] driver-core: Shut up dev_dbg_reatelimited() without DEBUG

[Hiroshi Doyu]

Hi Antti,

Antti Palosaari <crope@iki.fi> wrote @ Sat, 18 Aug 2012 02:11:56 +0200:

> On 08/17/2012 09:04 AM, Hiroshi Doyu wrote:
> > dev_dbg_reatelimited() without DEBUG printed "217078 callbacks
> > suppressed". This shouldn't print anything without DEBUG.
> >
> > Signed-off-by: Hiroshi Doyu <hdoyu@nvidia.com>
> > Reported-by: Antti Palosaari <crope@iki.fi>
> > ---
> >   include/linux/device.h |    6 +++++-
> >   1 files changed, 5 insertions(+), 1 deletions(-)
> >
> > diff --git a/include/linux/device.h b/include/linux/device.h
> > index eb945e1..d4dc26e 100644
> > --- a/include/linux/device.h
> > +++ b/include/linux/device.h
> > @@ -962,9 +962,13 @@ do {									\
> >   	dev_level_ratelimited(dev_notice, dev, fmt, ##__VA_ARGS__)
> >   #define dev_info_ratelimited(dev, fmt, ...)				\
> >   	dev_level_ratelimited(dev_info, dev, fmt, ##__VA_ARGS__)
> > +#if defined(DEBUG)
> >   #define dev_dbg_ratelimited(dev, fmt, ...)				\
> >   	dev_level_ratelimited(dev_dbg, dev, fmt, ##__VA_ARGS__)
> > -
> > +#else
> > +#define dev_dbg_ratelimited(dev, fmt, ...)			\
> > +	no_printk(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__)
> > +#endif
> >   /*
> >    * Stupid hackaround for existing uses of non-printk uses dev_info
> >    *
> >
>
> NACK. I don't think that's correct behavior. After that patch it kills
> all output of dev_dbg_ratelimited(). If I use dynamic debugs and order
> debugs, I expect to see debugs as earlier.

You are right. I attached the update patch, just moving *_ratelimited
functions after dev_dbg() definitions.

With DEBUG defined/undefined in your "test.ko", it works fine. With
CONFIG_DYNAMIC_DEBUG, it works with "+p", but with "-p", still
"..callbacks suppressed" is printed.

$ insmod test.ko
$ echo -n 'module test +p' > /sys/kernel/debug/dynamic_debug/control"
$ rmmod test
$ dmesg | tail -15
<7>[   69.047192] (NULL device *): print_dev_dbg_ratelimited: dev_dbg_ratelimited()
<7>[   69.047233] (NULL device *): print_dev_dbg_ratelimited: dev_dbg_ratelimited()
<7>[   69.047275] (NULL device *): print_dev_dbg_ratelimited: dev_dbg_ratelimited()
<4>[   75.057045] print_dev_dbg_ratelimited: 90 callbacks suppressed
<7>[   75.063595] (NULL device *): print_dev_dbg_ratelimited: dev_dbg_ratelimited()
<7>[   75.063796] (NULL device *): print_dev_dbg_ratelimited: dev_dbg_ratelimited()
<7>[   75.063970] (NULL device *): print_dev_dbg_ratelimited: dev_dbg_ratelimited()
<7>[   75.064137] (NULL device *): print_dev_dbg_ratelimited: dev_dbg_ratelimited()
<7>[   75.064307] (NULL device *): print_dev_dbg_ratelimited: dev_dbg_ratelimited()
<7>[   75.064472] (NULL device *): print_dev_dbg_ratelimited: dev_dbg_ratelimited()
<7>[   75.064640] (NULL device *): print_dev_dbg_ratelimited: dev_dbg_ratelimited()
<7>[   75.064806] (NULL device *): print_dev_dbg_ratelimited: dev_dbg_ratelimited()
<7>[   75.064972] (NULL device *): print_dev_dbg_ratelimited: dev_dbg_ratelimited()
<7>[   75.065137] (NULL device *): print_dev_dbg_ratelimited: dev_dbg_ratelimited()
<6>[   75.065510] test module unloaded!

$ insmod test.ko
$ echo -n 'module test -p' > /sys/kernel/debug/dynamic_debug/control"
$ rmmod test
$ dmesg
...
<6>[   82.715925] test module loaded!
<6>[   82.795642] dynamic_debug:ddebug_exec_queries: processed 1 queries, with 1 matches, 0 errs
<4>[   88.892096] print_dev_dbg_ratelimited: 90 callbacks suppressed
<6>[   88.898397] test module unloaded!

Any suggestion to control "... callbacks suppressed" with
CONFIG_DYNAMIC_DEBUG would be appreciated.

From 5b33751f89c2e91ee734325e6d73ed7e1c6d4b02 Mon Sep 17 00:00:00 2001
From: Hiroshi Doyu <hdoyu@nvidia.com>
Date: Mon, 20 Aug 2012 13:49:19 +0300
Subject: [PATCH 1/1] driver-core: Shut up dev_dbg_reatelimited() without
 DEBUG

dev_dbg_reatelimited() without DEBUG printed "217078 callbacks
suppressed". This shouldn't print anything without DEBUG.

With CONFIG_DYNAMIC_DEBUG, the print should be configured as expected.

Signed-off-by: Hiroshi Doyu <hdoyu@nvidia.com>
Reported-by: Antti Palosaari <crope@iki.fi>
---
 include/linux/device.h |   53 ++++++++++++++++++++++++++---------------------
 1 files changed, 29 insertions(+), 24 deletions(-)

diff --git a/include/linux/device.h b/include/linux/device.h
index 9648331..763bca4 100644
--- a/include/linux/device.h
+++ b/include/linux/device.h
@@ -932,6 +932,32 @@ int _dev_info(const struct device *dev, const char *fmt, ...)
 
 #endif
 
+/*
+ * Stupid hackaround for existing uses of non-printk uses dev_info
+ *
+ * Note that the definition of dev_info below is actually _dev_info
+ * and a macro is used to avoid redefining dev_info
+ */
+
+#define dev_info(dev, fmt, arg...) _dev_info(dev, fmt, ##arg)
+
+#if defined(CONFIG_DYNAMIC_DEBUG)
+#define dev_dbg(dev, format, ...)		     \
+do {						     \
+	dynamic_dev_dbg(dev, format, ##__VA_ARGS__); \
+} while (0)
+#elif defined(DEBUG)
+#define dev_dbg(dev, format, arg...)		\
+	dev_printk(KERN_DEBUG, dev, format, ##arg)
+#else
+#define dev_dbg(dev, format, arg...)				\
+({								\
+	if (0)							\
+		dev_printk(KERN_DEBUG, dev, format, ##arg);	\
+	0;							\
+})
+#endif
+
 #define dev_level_ratelimited(dev_level, dev, fmt, ...)			\
 do {									\
 	static DEFINE_RATELIMIT_STATE(_rs,				\
@@ -955,33 +981,12 @@ do {									\
 	dev_level_ratelimited(dev_notice, dev, fmt, ##__VA_ARGS__)
 #define dev_info_ratelimited(dev, fmt, ...)				\
 	dev_level_ratelimited(dev_info, dev, fmt, ##__VA_ARGS__)
+#if defined(CONFIG_DYNAMIC_DEBUG) || defined(DEBUG)
 #define dev_dbg_ratelimited(dev, fmt, ...)				\
 	dev_level_ratelimited(dev_dbg, dev, fmt, ##__VA_ARGS__)
-
-/*
- * Stupid hackaround for existing uses of non-printk uses dev_info
- *
- * Note that the definition of dev_info below is actually _dev_info
- * and a macro is used to avoid redefining dev_info
- */
-
-#define dev_info(dev, fmt, arg...) _dev_info(dev, fmt, ##arg)
-
-#if defined(CONFIG_DYNAMIC_DEBUG)
-#define dev_dbg(dev, format, ...)		     \
-do {						     \
-	dynamic_dev_dbg(dev, format, ##__VA_ARGS__); \
-} while (0)
-#elif defined(DEBUG)
-#define dev_dbg(dev, format, arg...)		\
-	dev_printk(KERN_DEBUG, dev, format, ##arg)
 #else
-#define dev_dbg(dev, format, arg...)				\
-({								\
-	if (0)							\
-		dev_printk(KERN_DEBUG, dev, format, ##arg);	\
-	0;							\
-})
+#define dev_dbg_ratelimited(dev, fmt, ...)			\
+	no_printk(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__)
 #endif
 
 #ifdef VERBOSE_DEBUG
-- 
1.7.5.4

Re: [PATCH 1/1] driver-core: Shut up dev_dbg_reatelimited() without DEBUG

[Antti Palosaari]

On 08/20/2012 02:14 PM, Hiroshi Doyu wrote:
> Hi Antti,
>
> Antti Palosaari <crope@iki.fi> wrote @ Sat, 18 Aug 2012 02:11:56 +0200:
>
>> On 08/17/2012 09:04 AM, Hiroshi Doyu wrote:
>>> dev_dbg_reatelimited() without DEBUG printed "217078 callbacks
>>> suppressed". This shouldn't print anything without DEBUG.
>>>
>>> Signed-off-by: Hiroshi Doyu <hdoyu@nvidia.com>
>>> Reported-by: Antti Palosaari <crope@iki.fi>
>>> ---
>>>    include/linux/device.h |    6 +++++-
>>>    1 files changed, 5 insertions(+), 1 deletions(-)
>>>
>>> diff --git a/include/linux/device.h b/include/linux/device.h
>>> index eb945e1..d4dc26e 100644
>>> --- a/include/linux/device.h
>>> +++ b/include/linux/device.h
>>> @@ -962,9 +962,13 @@ do {									\
>>>    	dev_level_ratelimited(dev_notice, dev, fmt, ##__VA_ARGS__)
>>>    #define dev_info_ratelimited(dev, fmt, ...)				\
>>>    	dev_level_ratelimited(dev_info, dev, fmt, ##__VA_ARGS__)
>>> +#if defined(DEBUG)
>>>    #define dev_dbg_ratelimited(dev, fmt, ...)				\
>>>    	dev_level_ratelimited(dev_dbg, dev, fmt, ##__VA_ARGS__)
>>> -
>>> +#else
>>> +#define dev_dbg_ratelimited(dev, fmt, ...)			\
>>> +	no_printk(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__)
>>> +#endif
>>>    /*
>>>     * Stupid hackaround for existing uses of non-printk uses dev_info
>>>     *
>>>
>>
>> NACK. I don't think that's correct behavior. After that patch it kills
>> all output of dev_dbg_ratelimited(). If I use dynamic debugs and order
>> debugs, I expect to see debugs as earlier.
>
> You are right. I attached the update patch, just moving *_ratelimited
> functions after dev_dbg() definitions.
>
> With DEBUG defined/undefined in your "test.ko", it works fine. With
> CONFIG_DYNAMIC_DEBUG, it works with "+p", but with "-p", still
> "..callbacks suppressed" is printed.

I am using dynamic debugs and behavior is now just same as it was when 
reported that bug. OK, likely for static debug it is now correct.

> $ insmod test.ko
> $ echo -n 'module test +p' > /sys/kernel/debug/dynamic_debug/control"
> $ rmmod test
> $ dmesg | tail -15
> <7>[   69.047192] (NULL device *): print_dev_dbg_ratelimited: dev_dbg_ratelimited()
> <7>[   69.047233] (NULL device *): print_dev_dbg_ratelimited: dev_dbg_ratelimited()
> <7>[   69.047275] (NULL device *): print_dev_dbg_ratelimited: dev_dbg_ratelimited()
> <4>[   75.057045] print_dev_dbg_ratelimited: 90 callbacks suppressed
> <7>[   75.063595] (NULL device *): print_dev_dbg_ratelimited: dev_dbg_ratelimited()
> <7>[   75.063796] (NULL device *): print_dev_dbg_ratelimited: dev_dbg_ratelimited()
> <7>[   75.063970] (NULL device *): print_dev_dbg_ratelimited: dev_dbg_ratelimited()
> <7>[   75.064137] (NULL device *): print_dev_dbg_ratelimited: dev_dbg_ratelimited()
> <7>[   75.064307] (NULL device *): print_dev_dbg_ratelimited: dev_dbg_ratelimited()
> <7>[   75.064472] (NULL device *): print_dev_dbg_ratelimited: dev_dbg_ratelimited()
> <7>[   75.064640] (NULL device *): print_dev_dbg_ratelimited: dev_dbg_ratelimited()
> <7>[   75.064806] (NULL device *): print_dev_dbg_ratelimited: dev_dbg_ratelimited()
> <7>[   75.064972] (NULL device *): print_dev_dbg_ratelimited: dev_dbg_ratelimited()
> <7>[   75.065137] (NULL device *): print_dev_dbg_ratelimited: dev_dbg_ratelimited()
> <6>[   75.065510] test module unloaded!
>
> $ insmod test.ko
> $ echo -n 'module test -p' > /sys/kernel/debug/dynamic_debug/control"
> $ rmmod test
> $ dmesg
> ...
> <6>[   82.715925] test module loaded!
> <6>[   82.795642] dynamic_debug:ddebug_exec_queries: processed 1 queries, with 1 matches, 0 errs
> <4>[   88.892096] print_dev_dbg_ratelimited: 90 callbacks suppressed
> <6>[   88.898397] test module unloaded!
>
> Any suggestion to control "... callbacks suppressed" with
> CONFIG_DYNAMIC_DEBUG would be appreciated.

Is it Joe Perches who has added these Kernel dynamic pr_ and dev_ 
debugging? Maybe he has proper solution that fixes ratelimit for dynamic 
debugging too.

regards
Antti

>
>>From 5b33751f89c2e91ee734325e6d73ed7e1c6d4b02 Mon Sep 17 00:00:00 2001
> From: Hiroshi Doyu <hdoyu@nvidia.com>
> Date: Mon, 20 Aug 2012 13:49:19 +0300
> Subject: [PATCH 1/1] driver-core: Shut up dev_dbg_reatelimited() without
>   DEBUG
>
> dev_dbg_reatelimited() without DEBUG printed "217078 callbacks
> suppressed". This shouldn't print anything without DEBUG.
>
> With CONFIG_DYNAMIC_DEBUG, the print should be configured as expected.
>
> Signed-off-by: Hiroshi Doyu <hdoyu@nvidia.com>
> Reported-by: Antti Palosaari <crope@iki.fi>
> ---
>   include/linux/device.h |   53 ++++++++++++++++++++++++++---------------------
>   1 files changed, 29 insertions(+), 24 deletions(-)
>
> diff --git a/include/linux/device.h b/include/linux/device.h
> index 9648331..763bca4 100644
> --- a/include/linux/device.h
> +++ b/include/linux/device.h
> @@ -932,6 +932,32 @@ int _dev_info(const struct device *dev, const char *fmt, ...)
>
>   #endif
>
> +/*
> + * Stupid hackaround for existing uses of non-printk uses dev_info
> + *
> + * Note that the definition of dev_info below is actually _dev_info
> + * and a macro is used to avoid redefining dev_info
> + */
> +
> +#define dev_info(dev, fmt, arg...) _dev_info(dev, fmt, ##arg)
> +
> +#if defined(CONFIG_DYNAMIC_DEBUG)
> +#define dev_dbg(dev, format, ...)		     \
> +do {						     \
> +	dynamic_dev_dbg(dev, format, ##__VA_ARGS__); \
> +} while (0)
> +#elif defined(DEBUG)
> +#define dev_dbg(dev, format, arg...)		\
> +	dev_printk(KERN_DEBUG, dev, format, ##arg)
> +#else
> +#define dev_dbg(dev, format, arg...)				\
> +({								\
> +	if (0)							\
> +		dev_printk(KERN_DEBUG, dev, format, ##arg);	\
> +	0;							\
> +})
> +#endif
> +
>   #define dev_level_ratelimited(dev_level, dev, fmt, ...)			\
>   do {									\
>   	static DEFINE_RATELIMIT_STATE(_rs,				\
> @@ -955,33 +981,12 @@ do {									\
>   	dev_level_ratelimited(dev_notice, dev, fmt, ##__VA_ARGS__)
>   #define dev_info_ratelimited(dev, fmt, ...)				\
>   	dev_level_ratelimited(dev_info, dev, fmt, ##__VA_ARGS__)
> +#if defined(CONFIG_DYNAMIC_DEBUG) || defined(DEBUG)
>   #define dev_dbg_ratelimited(dev, fmt, ...)				\
>   	dev_level_ratelimited(dev_dbg, dev, fmt, ##__VA_ARGS__)
> -
> -/*
> - * Stupid hackaround for existing uses of non-printk uses dev_info
> - *
> - * Note that the definition of dev_info below is actually _dev_info
> - * and a macro is used to avoid redefining dev_info
> - */
> -
> -#define dev_info(dev, fmt, arg...) _dev_info(dev, fmt, ##arg)
> -
> -#if defined(CONFIG_DYNAMIC_DEBUG)
> -#define dev_dbg(dev, format, ...)		     \
> -do {						     \
> -	dynamic_dev_dbg(dev, format, ##__VA_ARGS__); \
> -} while (0)
> -#elif defined(DEBUG)
> -#define dev_dbg(dev, format, arg...)		\
> -	dev_printk(KERN_DEBUG, dev, format, ##arg)
>   #else
> -#define dev_dbg(dev, format, arg...)				\
> -({								\
> -	if (0)							\
> -		dev_printk(KERN_DEBUG, dev, format, ##arg);	\
> -	0;							\
> -})
> +#define dev_dbg_ratelimited(dev, fmt, ...)			\
> +	no_printk(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__)
>   #endif
>
>   #ifdef VERBOSE_DEBUG
>


-- 
http://palosaari.fi/

Re: [PATCH 1/1] driver-core: Shut up dev_dbg_reatelimited() without DEBUG

[Hiroshi Doyu]

Antti Palosaari <crope@iki.fi> wrote @ Mon, 20 Aug 2012 23:29:34 +0200:

> On 08/20/2012 02:14 PM, Hiroshi Doyu wrote:
> > Hi Antti,
> >
> > Antti Palosaari <crope@iki.fi> wrote @ Sat, 18 Aug 2012 02:11:56 +0200:
> >
> >> On 08/17/2012 09:04 AM, Hiroshi Doyu wrote:
> >>> dev_dbg_reatelimited() without DEBUG printed "217078 callbacks
> >>> suppressed". This shouldn't print anything without DEBUG.
> >>>
> >>> Signed-off-by: Hiroshi Doyu <hdoyu@nvidia.com>
> >>> Reported-by: Antti Palosaari <crope@iki.fi>
> >>> ---
> >>>    include/linux/device.h |    6 +++++-
> >>>    1 files changed, 5 insertions(+), 1 deletions(-)
> >>>
> >>> diff --git a/include/linux/device.h b/include/linux/device.h
> >>> index eb945e1..d4dc26e 100644
> >>> --- a/include/linux/device.h
> >>> +++ b/include/linux/device.h
> >>> @@ -962,9 +962,13 @@ do {									\
> >>>    	dev_level_ratelimited(dev_notice, dev, fmt, ##__VA_ARGS__)
> >>>    #define dev_info_ratelimited(dev, fmt, ...)				\
> >>>    	dev_level_ratelimited(dev_info, dev, fmt, ##__VA_ARGS__)
> >>> +#if defined(DEBUG)
> >>>    #define dev_dbg_ratelimited(dev, fmt, ...)				\
> >>>    	dev_level_ratelimited(dev_dbg, dev, fmt, ##__VA_ARGS__)
> >>> -
> >>> +#else
> >>> +#define dev_dbg_ratelimited(dev, fmt, ...)			\
> >>> +	no_printk(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__)
> >>> +#endif
> >>>    /*
> >>>     * Stupid hackaround for existing uses of non-printk uses dev_info
> >>>     *
> >>>
> >>
> >> NACK. I don't think that's correct behavior. After that patch it kills
> >> all output of dev_dbg_ratelimited(). If I use dynamic debugs and order
> >> debugs, I expect to see debugs as earlier.
> >
> > You are right. I attached the update patch, just moving *_ratelimited
> > functions after dev_dbg() definitions.
> >
> > With DEBUG defined/undefined in your "test.ko", it works fine. With
> > CONFIG_DYNAMIC_DEBUG, it works with "+p", but with "-p", still
> > "..callbacks suppressed" is printed.
> 
> I am using dynamic debugs and behavior is now just same as it was when 
> reported that bug. OK, likely for static debug it is now correct.

The following patch can also refrain "..callbacks suppressed" with
"-p". I think that it's ok for all cases.

From b4c6aa9160f03b61ed17975c73db36c983a48927 Mon Sep 17 00:00:00 2001
From: Hiroshi Doyu <hdoyu@nvidia.com>
Date: Mon, 20 Aug 2012 13:49:19 +0300
Subject: [v3 1/1] driver-core: Shut up dev_dbg_reatelimited() without DEBUG

dev_dbg_reatelimited() without DEBUG printed "217078 callbacks
suppressed". This shouldn't print anything without DEBUG.

With CONFIG_DYNAMIC_DEBUG, the print should be configured as expected.

Signed-off-by: Hiroshi Doyu <hdoyu@nvidia.com>
Reported-by: Antti Palosaari <crope@iki.fi>
---
 include/linux/device.h |   62 +++++++++++++++++++++++++++++------------------
 1 files changed, 38 insertions(+), 24 deletions(-)

diff --git a/include/linux/device.h b/include/linux/device.h
index 9648331..bb6ffcb 100644
--- a/include/linux/device.h
+++ b/include/linux/device.h
@@ -932,6 +932,32 @@ int _dev_info(const struct device *dev, const char *fmt, ...)
 
 #endif
 
+/*
+ * Stupid hackaround for existing uses of non-printk uses dev_info
+ *
+ * Note that the definition of dev_info below is actually _dev_info
+ * and a macro is used to avoid redefining dev_info
+ */
+
+#define dev_info(dev, fmt, arg...) _dev_info(dev, fmt, ##arg)
+
+#if defined(CONFIG_DYNAMIC_DEBUG)
+#define dev_dbg(dev, format, ...)		     \
+do {						     \
+	dynamic_dev_dbg(dev, format, ##__VA_ARGS__); \
+} while (0)
+#elif defined(DEBUG)
+#define dev_dbg(dev, format, arg...)		\
+	dev_printk(KERN_DEBUG, dev, format, ##arg)
+#else
+#define dev_dbg(dev, format, arg...)				\
+({								\
+	if (0)							\
+		dev_printk(KERN_DEBUG, dev, format, ##arg);	\
+	0;							\
+})
+#endif
+
 #define dev_level_ratelimited(dev_level, dev, fmt, ...)			\
 do {									\
 	static DEFINE_RATELIMIT_STATE(_rs,				\
@@ -955,33 +981,21 @@ do {									\
 	dev_level_ratelimited(dev_notice, dev, fmt, ##__VA_ARGS__)
 #define dev_info_ratelimited(dev, fmt, ...)				\
 	dev_level_ratelimited(dev_info, dev, fmt, ##__VA_ARGS__)
+#if defined(CONFIG_DYNAMIC_DEBUG) || defined(DEBUG)
 #define dev_dbg_ratelimited(dev, fmt, ...)				\
-	dev_level_ratelimited(dev_dbg, dev, fmt, ##__VA_ARGS__)
-
-/*
- * Stupid hackaround for existing uses of non-printk uses dev_info
- *
- * Note that the definition of dev_info below is actually _dev_info
- * and a macro is used to avoid redefining dev_info
- */
-
-#define dev_info(dev, fmt, arg...) _dev_info(dev, fmt, ##arg)
-
-#if defined(CONFIG_DYNAMIC_DEBUG)
-#define dev_dbg(dev, format, ...)		     \
-do {						     \
-	dynamic_dev_dbg(dev, format, ##__VA_ARGS__); \
+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, pr_fmt(fmt),		\
+				   ##__VA_ARGS__);			\
 } while (0)
-#elif defined(DEBUG)
-#define dev_dbg(dev, format, arg...)		\
-	dev_printk(KERN_DEBUG, dev, format, ##arg)
 #else
-#define dev_dbg(dev, format, arg...)				\
-({								\
-	if (0)							\
-		dev_printk(KERN_DEBUG, dev, format, ##arg);	\
-	0;							\
-})
+#define dev_dbg_ratelimited(dev, fmt, ...)			\
+	no_printk(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__)
 #endif
 
 #ifdef VERBOSE_DEBUG
-- 
1.7.5.4

Re: [PATCH 1/1] driver-core: Shut up dev_dbg_reatelimited() without DEBUG

[Antti Palosaari]

Hello Hiroshi,

On 08/21/2012 10:02 AM, Hiroshi Doyu wrote:
> Antti Palosaari <crope@iki.fi> wrote @ Mon, 20 Aug 2012 23:29:34 +0200:
>
>> On 08/20/2012 02:14 PM, Hiroshi Doyu wrote:
>>> Hi Antti,
>>>
>>> Antti Palosaari <crope@iki.fi> wrote @ Sat, 18 Aug 2012 02:11:56 +0200:
>>>
>>>> On 08/17/2012 09:04 AM, Hiroshi Doyu wrote:
>>>>> dev_dbg_reatelimited() without DEBUG printed "217078 callbacks
>>>>> suppressed". This shouldn't print anything without DEBUG.
>>>>>
>>>>> Signed-off-by: Hiroshi Doyu <hdoyu@nvidia.com>
>>>>> Reported-by: Antti Palosaari <crope@iki.fi>
>>>>> ---
>>>>>     include/linux/device.h |    6 +++++-
>>>>>     1 files changed, 5 insertions(+), 1 deletions(-)
>>>>>
>>>>> diff --git a/include/linux/device.h b/include/linux/device.h
>>>>> index eb945e1..d4dc26e 100644
>>>>> --- a/include/linux/device.h
>>>>> +++ b/include/linux/device.h
>>>>> @@ -962,9 +962,13 @@ do {									\
>>>>>     	dev_level_ratelimited(dev_notice, dev, fmt, ##__VA_ARGS__)
>>>>>     #define dev_info_ratelimited(dev, fmt, ...)				\
>>>>>     	dev_level_ratelimited(dev_info, dev, fmt, ##__VA_ARGS__)
>>>>> +#if defined(DEBUG)
>>>>>     #define dev_dbg_ratelimited(dev, fmt, ...)				\
>>>>>     	dev_level_ratelimited(dev_dbg, dev, fmt, ##__VA_ARGS__)
>>>>> -
>>>>> +#else
>>>>> +#define dev_dbg_ratelimited(dev, fmt, ...)			\
>>>>> +	no_printk(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__)
>>>>> +#endif
>>>>>     /*
>>>>>      * Stupid hackaround for existing uses of non-printk uses dev_info
>>>>>      *
>>>>>
>>>>
>>>> NACK. I don't think that's correct behavior. After that patch it kills
>>>> all output of dev_dbg_ratelimited(). If I use dynamic debugs and order
>>>> debugs, I expect to see debugs as earlier.
>>>
>>> You are right. I attached the update patch, just moving *_ratelimited
>>> functions after dev_dbg() definitions.
>>>
>>> With DEBUG defined/undefined in your "test.ko", it works fine. With
>>> CONFIG_DYNAMIC_DEBUG, it works with "+p", but with "-p", still
>>> "..callbacks suppressed" is printed.
>>
>> I am using dynamic debugs and behavior is now just same as it was when
>> reported that bug. OK, likely for static debug it is now correct.
>
> The following patch can also refrain "..callbacks suppressed" with
> "-p". I think that it's ok for all cases.
>
>>From b4c6aa9160f03b61ed17975c73db36c983a48927 Mon Sep 17 00:00:00 2001
> From: Hiroshi Doyu <hdoyu@nvidia.com>
> Date: Mon, 20 Aug 2012 13:49:19 +0300
> Subject: [v3 1/1] driver-core: Shut up dev_dbg_reatelimited() without DEBUG
>
> dev_dbg_reatelimited() without DEBUG printed "217078 callbacks
> suppressed". This shouldn't print anything without DEBUG.
>
> With CONFIG_DYNAMIC_DEBUG, the print should be configured as expected.
>
> Signed-off-by: Hiroshi Doyu <hdoyu@nvidia.com>
> Reported-by: Antti Palosaari <crope@iki.fi>
> ---
>   include/linux/device.h |   62 +++++++++++++++++++++++++++++------------------
>   1 files changed, 38 insertions(+), 24 deletions(-)
>
> diff --git a/include/linux/device.h b/include/linux/device.h
> index 9648331..bb6ffcb 100644
> --- a/include/linux/device.h
> +++ b/include/linux/device.h
> @@ -932,6 +932,32 @@ int _dev_info(const struct device *dev, const char *fmt, ...)
>
>   #endif
>
> +/*
> + * Stupid hackaround for existing uses of non-printk uses dev_info
> + *
> + * Note that the definition of dev_info below is actually _dev_info
> + * and a macro is used to avoid redefining dev_info
> + */
> +
> +#define dev_info(dev, fmt, arg...) _dev_info(dev, fmt, ##arg)
> +
> +#if defined(CONFIG_DYNAMIC_DEBUG)
> +#define dev_dbg(dev, format, ...)		     \
> +do {						     \
> +	dynamic_dev_dbg(dev, format, ##__VA_ARGS__); \
> +} while (0)
> +#elif defined(DEBUG)
> +#define dev_dbg(dev, format, arg...)		\
> +	dev_printk(KERN_DEBUG, dev, format, ##arg)
> +#else
> +#define dev_dbg(dev, format, arg...)				\
> +({								\
> +	if (0)							\
> +		dev_printk(KERN_DEBUG, dev, format, ##arg);	\
> +	0;							\
> +})
> +#endif
> +
>   #define dev_level_ratelimited(dev_level, dev, fmt, ...)			\
>   do {									\
>   	static DEFINE_RATELIMIT_STATE(_rs,				\
> @@ -955,33 +981,21 @@ do {									\
>   	dev_level_ratelimited(dev_notice, dev, fmt, ##__VA_ARGS__)
>   #define dev_info_ratelimited(dev, fmt, ...)				\
>   	dev_level_ratelimited(dev_info, dev, fmt, ##__VA_ARGS__)
> +#if defined(CONFIG_DYNAMIC_DEBUG) || defined(DEBUG)
>   #define dev_dbg_ratelimited(dev, fmt, ...)				\
> -	dev_level_ratelimited(dev_dbg, dev, fmt, ##__VA_ARGS__)
> -
> -/*
> - * Stupid hackaround for existing uses of non-printk uses dev_info
> - *
> - * Note that the definition of dev_info below is actually _dev_info
> - * and a macro is used to avoid redefining dev_info
> - */
> -
> -#define dev_info(dev, fmt, arg...) _dev_info(dev, fmt, ##arg)
> -
> -#if defined(CONFIG_DYNAMIC_DEBUG)
> -#define dev_dbg(dev, format, ...)		     \
> -do {						     \
> -	dynamic_dev_dbg(dev, format, ##__VA_ARGS__); \
> +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, pr_fmt(fmt),		\
> +				   ##__VA_ARGS__);			\
>   } while (0)
> -#elif defined(DEBUG)
> -#define dev_dbg(dev, format, arg...)		\
> -	dev_printk(KERN_DEBUG, dev, format, ##arg)
>   #else
> -#define dev_dbg(dev, format, arg...)				\
> -({								\
> -	if (0)							\
> -		dev_printk(KERN_DEBUG, dev, format, ##arg);	\
> -	0;							\
> -})
> +#define dev_dbg_ratelimited(dev, fmt, ...)			\
> +	no_printk(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__)
>   #endif
>
>   #ifdef VERBOSE_DEBUG

That seems to work correctly now. I tested it using dynamic debugs. It 
was Hin-Tak who originally reported that bug for me after I added few 
ratelimited debugs for DVB stack. Thank you!

Reported-by: Hin-Tak Leung <htl10@users.sourceforge.net>
Tested-by: Antti Palosaari <crope@iki.fi>


regards
Antti

-- 
http://palosaari.fi/

Re: [PATCH 1/1] driver-core: Shut up dev_dbg_reatelimited() without DEBUG

[Hin-Tak Leung]

Antti Palosaari wrote:
> Hello Hiroshi,
>
> On 08/21/2012 10:02 AM, Hiroshi Doyu wrote:
>> Antti Palosaari <crope-X3B1VOXEql0@public.gmane.org> wrote @ Mon, 20 Aug 2012 23:29:34 +0200:
>>
>>> On 08/20/2012 02:14 PM, Hiroshi Doyu wrote:
>>>> Hi Antti,
>>>>
>>>> Antti Palosaari <crope-X3B1VOXEql0@public.gmane.org> wrote @ Sat, 18 Aug 2012 02:11:56 +0200:
>>>>
>>>>> On 08/17/2012 09:04 AM, Hiroshi Doyu wrote:
>>>>>> dev_dbg_reatelimited() without DEBUG printed "217078 callbacks
>>>>>> suppressed". This shouldn't print anything without DEBUG.
>>>>>>
>>>>>> Signed-off-by: Hiroshi Doyu <hdoyu-DDmLM1+adcrQT0dZR+AlfA@public.gmane.org>
>>>>>> Reported-by: Antti Palosaari <crope-X3B1VOXEql0@public.gmane.org>
>>>>>> ---
>>>>>>     include/linux/device.h |    6 +++++-
>>>>>>     1 files changed, 5 insertions(+), 1 deletions(-)
>>>>>>
>>>>>> diff --git a/include/linux/device.h b/include/linux/device.h
>>>>>> index eb945e1..d4dc26e 100644
>>>>>> --- a/include/linux/device.h
>>>>>> +++ b/include/linux/device.h
>>>>>> @@ -962,9 +962,13 @@ do {                                    \
>>>>>>         dev_level_ratelimited(dev_notice, dev, fmt, ##__VA_ARGS__)
>>>>>>     #define dev_info_ratelimited(dev, fmt, ...)                \
>>>>>>         dev_level_ratelimited(dev_info, dev, fmt, ##__VA_ARGS__)
>>>>>> +#if defined(DEBUG)
>>>>>>     #define dev_dbg_ratelimited(dev, fmt, ...)                \
>>>>>>         dev_level_ratelimited(dev_dbg, dev, fmt, ##__VA_ARGS__)
>>>>>> -
>>>>>> +#else
>>>>>> +#define dev_dbg_ratelimited(dev, fmt, ...)            \
>>>>>> +    no_printk(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__)
>>>>>> +#endif
>>>>>>     /*
>>>>>>      * Stupid hackaround for existing uses of non-printk uses dev_info
>>>>>>      *
>>>>>>
>>>>>
>>>>> NACK. I don't think that's correct behavior. After that patch it kills
>>>>> all output of dev_dbg_ratelimited(). If I use dynamic debugs and order
>>>>> debugs, I expect to see debugs as earlier.
>>>>
>>>> You are right. I attached the update patch, just moving *_ratelimited
>>>> functions after dev_dbg() definitions.
>>>>
>>>> With DEBUG defined/undefined in your "test.ko", it works fine. With
>>>> CONFIG_DYNAMIC_DEBUG, it works with "+p", but with "-p", still
>>>> "..callbacks suppressed" is printed.
>>>
>>> I am using dynamic debugs and behavior is now just same as it was when
>>> reported that bug. OK, likely for static debug it is now correct.
>>
>> The following patch can also refrain "..callbacks suppressed" with
>> "-p". I think that it's ok for all cases.
>>
>>> From b4c6aa9160f03b61ed17975c73db36c983a48927 Mon Sep 17 00:00:00 2001
>> From: Hiroshi Doyu <hdoyu-DDmLM1+adcrQT0dZR+AlfA@public.gmane.org>
>> Date: Mon, 20 Aug 2012 13:49:19 +0300
>> Subject: [v3 1/1] driver-core: Shut up dev_dbg_reatelimited() without DEBUG
>>
>> dev_dbg_reatelimited() without DEBUG printed "217078 callbacks
>> suppressed". This shouldn't print anything without DEBUG.
>>
>> With CONFIG_DYNAMIC_DEBUG, the print should be configured as expected.
>>
>> Signed-off-by: Hiroshi Doyu <hdoyu-DDmLM1+adcrQT0dZR+AlfA@public.gmane.org>
>> Reported-by: Antti Palosaari <crope-X3B1VOXEql0@public.gmane.org>
>> ---
>>   include/linux/device.h |   62 +++++++++++++++++++++++++++++------------------
>>   1 files changed, 38 insertions(+), 24 deletions(-)
>>
>> diff --git a/include/linux/device.h b/include/linux/device.h
>> index 9648331..bb6ffcb 100644
>> --- a/include/linux/device.h
>> +++ b/include/linux/device.h
>> @@ -932,6 +932,32 @@ int _dev_info(const struct device *dev, const char *fmt,
>> ...)
>>
>>   #endif
>>
>> +/*
>> + * Stupid hackaround for existing uses of non-printk uses dev_info
>> + *
>> + * Note that the definition of dev_info below is actually _dev_info
>> + * and a macro is used to avoid redefining dev_info
>> + */
>> +
>> +#define dev_info(dev, fmt, arg...) _dev_info(dev, fmt, ##arg)
>> +
>> +#if defined(CONFIG_DYNAMIC_DEBUG)
>> +#define dev_dbg(dev, format, ...)             \
>> +do {                             \
>> +    dynamic_dev_dbg(dev, format, ##__VA_ARGS__); \
>> +} while (0)
>> +#elif defined(DEBUG)
>> +#define dev_dbg(dev, format, arg...)        \
>> +    dev_printk(KERN_DEBUG, dev, format, ##arg)
>> +#else
>> +#define dev_dbg(dev, format, arg...)                \
>> +({                                \
>> +    if (0)                            \
>> +        dev_printk(KERN_DEBUG, dev, format, ##arg);    \
>> +    0;                            \
>> +})
>> +#endif
>> +
>>   #define dev_level_ratelimited(dev_level, dev, fmt, ...)            \
>>   do {                                    \
>>       static DEFINE_RATELIMIT_STATE(_rs,                \
>> @@ -955,33 +981,21 @@ do {                                    \
>>       dev_level_ratelimited(dev_notice, dev, fmt, ##__VA_ARGS__)
>>   #define dev_info_ratelimited(dev, fmt, ...)                \
>>       dev_level_ratelimited(dev_info, dev, fmt, ##__VA_ARGS__)
>> +#if defined(CONFIG_DYNAMIC_DEBUG) || defined(DEBUG)
>>   #define dev_dbg_ratelimited(dev, fmt, ...)                \
>> -    dev_level_ratelimited(dev_dbg, dev, fmt, ##__VA_ARGS__)
>> -
>> -/*
>> - * Stupid hackaround for existing uses of non-printk uses dev_info
>> - *
>> - * Note that the definition of dev_info below is actually _dev_info
>> - * and a macro is used to avoid redefining dev_info
>> - */
>> -
>> -#define dev_info(dev, fmt, arg...) _dev_info(dev, fmt, ##arg)
>> -
>> -#if defined(CONFIG_DYNAMIC_DEBUG)
>> -#define dev_dbg(dev, format, ...)             \
>> -do {                             \
>> -    dynamic_dev_dbg(dev, format, ##__VA_ARGS__); \
>> +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, pr_fmt(fmt),        \
>> +                   ##__VA_ARGS__);            \
>>   } while (0)
>> -#elif defined(DEBUG)
>> -#define dev_dbg(dev, format, arg...)        \
>> -    dev_printk(KERN_DEBUG, dev, format, ##arg)
>>   #else
>> -#define dev_dbg(dev, format, arg...)                \
>> -({                                \
>> -    if (0)                            \
>> -        dev_printk(KERN_DEBUG, dev, format, ##arg);    \
>> -    0;                            \
>> -})
>> +#define dev_dbg_ratelimited(dev, fmt, ...)            \
>> +    no_printk(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__)
>>   #endif
>>
>>   #ifdef VERBOSE_DEBUG
>
> That seems to work correctly now. I tested it using dynamic debugs. It was
> Hin-Tak who originally reported that bug for me after I added few ratelimited
> debugs for DVB stack. Thank you!
>
> Reported-by: Hin-Tak Leung <htl10-Rn4VEauK+AKRv+LV9MX5uipxlwaOVQ5f@public.gmane.org>
> Tested-by: Antti Palosaari <crope-X3B1VOXEql0@public.gmane.org>
>
>
> regards
> Antti
>

This is with mediatree/for_v3.7-8 , playing DVB-T video with mplayer.

echo 'file ...media_build/v4l/usb_urb.c +p' > 
/sys/kernel/debug/dynamic_debug/control

With +p

[137749.698202] usb 1-3: usb_urb_complete: bulk urb completed status=0 
length=4096/4096 pack_num=0 errors=0
[137749.699449] usb 1-3: usb_urb_complete: bulk urb completed status=0 
length=4096/4096 pack_num=0 errors=0
[137749.700825] usb 1-3: usb_urb_complete: bulk urb completed status=0 
length=4096/4096 pack_num=0 errors=0
[137754.690862] usb_urb_complete: 3570 callbacks suppressed
[137754.690888] usb 1-3: usb_urb_complete: bulk urb completed status=0 
length=4096/4096 pack_num=0 errors=0
[137754.692489] usb 1-3: usb_urb_complete: bulk urb completed status=0 
length=4096/4096 pack_num=0 errors=0
[137754.693745] usb 1-3: usb_urb_complete: bulk urb completed status=0 
length=4096/4096 pack_num=0 errors=0
[137754.694882] usb 1-3: usb_urb_complete: bulk urb completed status=0 
length=4096/4096 pack_num=0 errors=0
[137754.696240] usb 1-3: usb_urb_complete: bulk urb completed status=0 
length=4096/4096 pack_num=0 errors=0
[137754.697483] usb 1-3: usb_urb_complete: bulk urb completed status=0 
length=4096/4096 pack_num=0 errors=0
[137754.699002] usb 1-3: usb_urb_complete: bulk urb completed status=0 
length=4096/4096 pack_num=0 errors=0
[137754.700884] usb 1-3: usb_urb_complete: bulk urb completed status=0 
length=4096/4096 pack_num=0 errors=0
[137754.701613] usb 1-3: usb_urb_complete: bulk urb completed status=0 
length=4096/4096 pack_num=0 errors=0
[137754.702986] usb 1-3: usb_urb_complete: bulk urb completed status=0 
length=4096/4096 pack_num=0 errors=0
[137759.695906] usb_urb_complete: 3595 callbacks suppressed
[137759.695934] usb 1-3: usb_urb_complete: bulk urb completed status=0 
length=4096/4096 pack_num=0 errors=0
[137759.697788] usb 1-3: usb_urb_complete: bulk urb completed status=0 
length=4096/4096 pack_num=0 errors=0
[137759.698772] usb 1-3: usb_urb_complete: bulk urb completed status=0 
length=4096/4096 pack_num=0 errors=0

with -p

[137814.730303] usb_urb_complete: 3555 callbacks suppressed
[137819.740698] usb_urb_complete: 3519 callbacks suppressed
[137824.744857] usb_urb_complete: 3443 callbacks suppressed
[137829.746023] usb_urb_complete: 3345 callbacks suppressed
[137834.749931] usb_urb_complete: 3558 callbacks suppressed
[137839.753102] usb_urb_complete: 3465 callbacks suppressed
[137844.755521] usb_urb_complete: 3438 callbacks suppressed

Re: [PATCH 1/1] driver-core: Shut up dev_dbg_reatelimited() without DEBUG

[Antti Palosaari]

On 08/22/2012 04:57 PM, Hin-Tak Leung wrote:
> Antti Palosaari wrote:
>> Hello Hiroshi,
>>
>> On 08/21/2012 10:02 AM, Hiroshi Doyu wrote:
>>> Antti Palosaari <crope-X3B1VOXEql0@public.gmane.org> wrote @ Mon, 20 Aug 2012 23:29:34 +0200:
>>>
>>>> On 08/20/2012 02:14 PM, Hiroshi Doyu wrote:
>>>>> Hi Antti,
>>>>>
>>>>> Antti Palosaari <crope-X3B1VOXEql0@public.gmane.org> wrote @ Sat, 18 Aug 2012 02:11:56
>>>>> +0200:
>>>>>
>>>>>> On 08/17/2012 09:04 AM, Hiroshi Doyu wrote:
>>>>>>> dev_dbg_reatelimited() without DEBUG printed "217078 callbacks
>>>>>>> suppressed". This shouldn't print anything without DEBUG.
>>>>>>>
>>>>>>> Signed-off-by: Hiroshi Doyu <hdoyu-DDmLM1+adcrQT0dZR+AlfA@public.gmane.org>
>>>>>>> Reported-by: Antti Palosaari <crope-X3B1VOXEql0@public.gmane.org>
>>>>>>> ---
>>>>>>>     include/linux/device.h |    6 +++++-
>>>>>>>     1 files changed, 5 insertions(+), 1 deletions(-)
>>>>>>>
>>>>>>> diff --git a/include/linux/device.h b/include/linux/device.h
>>>>>>> index eb945e1..d4dc26e 100644
>>>>>>> --- a/include/linux/device.h
>>>>>>> +++ b/include/linux/device.h
>>>>>>> @@ -962,9 +962,13 @@ do {                                    \
>>>>>>>         dev_level_ratelimited(dev_notice, dev, fmt, ##__VA_ARGS__)
>>>>>>>     #define dev_info_ratelimited(dev, fmt, ...)                \
>>>>>>>         dev_level_ratelimited(dev_info, dev, fmt, ##__VA_ARGS__)
>>>>>>> +#if defined(DEBUG)
>>>>>>>     #define dev_dbg_ratelimited(dev, fmt, ...)                \
>>>>>>>         dev_level_ratelimited(dev_dbg, dev, fmt, ##__VA_ARGS__)
>>>>>>> -
>>>>>>> +#else
>>>>>>> +#define dev_dbg_ratelimited(dev, fmt, ...)            \
>>>>>>> +    no_printk(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__)
>>>>>>> +#endif
>>>>>>>     /*
>>>>>>>      * Stupid hackaround for existing uses of non-printk uses
>>>>>>> dev_info
>>>>>>>      *
>>>>>>>
>>>>>>
>>>>>> NACK. I don't think that's correct behavior. After that patch it
>>>>>> kills
>>>>>> all output of dev_dbg_ratelimited(). If I use dynamic debugs and
>>>>>> order
>>>>>> debugs, I expect to see debugs as earlier.
>>>>>
>>>>> You are right. I attached the update patch, just moving *_ratelimited
>>>>> functions after dev_dbg() definitions.
>>>>>
>>>>> With DEBUG defined/undefined in your "test.ko", it works fine. With
>>>>> CONFIG_DYNAMIC_DEBUG, it works with "+p", but with "-p", still
>>>>> "..callbacks suppressed" is printed.
>>>>
>>>> I am using dynamic debugs and behavior is now just same as it was when
>>>> reported that bug. OK, likely for static debug it is now correct.
>>>
>>> The following patch can also refrain "..callbacks suppressed" with
>>> "-p". I think that it's ok for all cases.
>>>
>>>> From b4c6aa9160f03b61ed17975c73db36c983a48927 Mon Sep 17 00:00:00 2001
>>> From: Hiroshi Doyu <hdoyu-DDmLM1+adcrQT0dZR+AlfA@public.gmane.org>
>>> Date: Mon, 20 Aug 2012 13:49:19 +0300
>>> Subject: [v3 1/1] driver-core: Shut up dev_dbg_reatelimited() without
>>> DEBUG
>>>
>>> dev_dbg_reatelimited() without DEBUG printed "217078 callbacks
>>> suppressed". This shouldn't print anything without DEBUG.
>>>
>>> With CONFIG_DYNAMIC_DEBUG, the print should be configured as expected.
>>>
>>> Signed-off-by: Hiroshi Doyu <hdoyu-DDmLM1+adcrQT0dZR+AlfA@public.gmane.org>
>>> Reported-by: Antti Palosaari <crope-X3B1VOXEql0@public.gmane.org>
>>> ---
>>>   include/linux/device.h |   62
>>> +++++++++++++++++++++++++++++------------------
>>>   1 files changed, 38 insertions(+), 24 deletions(-)
>>>
>>> diff --git a/include/linux/device.h b/include/linux/device.h
>>> index 9648331..bb6ffcb 100644
>>> --- a/include/linux/device.h
>>> +++ b/include/linux/device.h
>>> @@ -932,6 +932,32 @@ int _dev_info(const struct device *dev, const
>>> char *fmt,
>>> ...)
>>>
>>>   #endif
>>>
>>> +/*
>>> + * Stupid hackaround for existing uses of non-printk uses dev_info
>>> + *
>>> + * Note that the definition of dev_info below is actually _dev_info
>>> + * and a macro is used to avoid redefining dev_info
>>> + */
>>> +
>>> +#define dev_info(dev, fmt, arg...) _dev_info(dev, fmt, ##arg)
>>> +
>>> +#if defined(CONFIG_DYNAMIC_DEBUG)
>>> +#define dev_dbg(dev, format, ...)             \
>>> +do {                             \
>>> +    dynamic_dev_dbg(dev, format, ##__VA_ARGS__); \
>>> +} while (0)
>>> +#elif defined(DEBUG)
>>> +#define dev_dbg(dev, format, arg...)        \
>>> +    dev_printk(KERN_DEBUG, dev, format, ##arg)
>>> +#else
>>> +#define dev_dbg(dev, format, arg...)                \
>>> +({                                \
>>> +    if (0)                            \
>>> +        dev_printk(KERN_DEBUG, dev, format, ##arg);    \
>>> +    0;                            \
>>> +})
>>> +#endif
>>> +
>>>   #define dev_level_ratelimited(dev_level, dev, fmt, ...)            \
>>>   do {                                    \
>>>       static DEFINE_RATELIMIT_STATE(_rs,                \
>>> @@ -955,33 +981,21 @@ do {                                    \
>>>       dev_level_ratelimited(dev_notice, dev, fmt, ##__VA_ARGS__)
>>>   #define dev_info_ratelimited(dev, fmt, ...)                \
>>>       dev_level_ratelimited(dev_info, dev, fmt, ##__VA_ARGS__)
>>> +#if defined(CONFIG_DYNAMIC_DEBUG) || defined(DEBUG)
>>>   #define dev_dbg_ratelimited(dev, fmt, ...)                \
>>> -    dev_level_ratelimited(dev_dbg, dev, fmt, ##__VA_ARGS__)
>>> -
>>> -/*
>>> - * Stupid hackaround for existing uses of non-printk uses dev_info
>>> - *
>>> - * Note that the definition of dev_info below is actually _dev_info
>>> - * and a macro is used to avoid redefining dev_info
>>> - */
>>> -
>>> -#define dev_info(dev, fmt, arg...) _dev_info(dev, fmt, ##arg)
>>> -
>>> -#if defined(CONFIG_DYNAMIC_DEBUG)
>>> -#define dev_dbg(dev, format, ...)             \
>>> -do {                             \
>>> -    dynamic_dev_dbg(dev, format, ##__VA_ARGS__); \
>>> +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, pr_fmt(fmt),        \
>>> +                   ##__VA_ARGS__);            \
>>>   } while (0)
>>> -#elif defined(DEBUG)
>>> -#define dev_dbg(dev, format, arg...)        \
>>> -    dev_printk(KERN_DEBUG, dev, format, ##arg)
>>>   #else
>>> -#define dev_dbg(dev, format, arg...)                \
>>> -({                                \
>>> -    if (0)                            \
>>> -        dev_printk(KERN_DEBUG, dev, format, ##arg);    \
>>> -    0;                            \
>>> -})
>>> +#define dev_dbg_ratelimited(dev, fmt, ...)            \
>>> +    no_printk(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__)
>>>   #endif
>>>
>>>   #ifdef VERBOSE_DEBUG
>>
>> That seems to work correctly now. I tested it using dynamic debugs. It
>> was
>> Hin-Tak who originally reported that bug for me after I added few
>> ratelimited
>> debugs for DVB stack. Thank you!
>>
>> Reported-by: Hin-Tak Leung <htl10-Rn4VEauK+AKRv+LV9MX5uipxlwaOVQ5f@public.gmane.org>
>> Tested-by: Antti Palosaari <crope-X3B1VOXEql0@public.gmane.org>
>>
>>
>> regards
>> Antti
>>
>
> This is with mediatree/for_v3.7-8 , playing DVB-T video with mplayer.
>
> echo 'file ...media_build/v4l/usb_urb.c +p' >
> /sys/kernel/debug/dynamic_debug/control
>
> With +p
>
> [137749.698202] usb 1-3: usb_urb_complete: bulk urb completed status=0
> length=4096/4096 pack_num=0 errors=0
> [137749.699449] usb 1-3: usb_urb_complete: bulk urb completed status=0
> length=4096/4096 pack_num=0 errors=0
> [137749.700825] usb 1-3: usb_urb_complete: bulk urb completed status=0
> length=4096/4096 pack_num=0 errors=0
> [137754.690862] usb_urb_complete: 3570 callbacks suppressed
> [137754.690888] usb 1-3: usb_urb_complete: bulk urb completed status=0
> length=4096/4096 pack_num=0 errors=0
> [137754.692489] usb 1-3: usb_urb_complete: bulk urb completed status=0
> length=4096/4096 pack_num=0 errors=0
> [137754.693745] usb 1-3: usb_urb_complete: bulk urb completed status=0
> length=4096/4096 pack_num=0 errors=0
> [137754.694882] usb 1-3: usb_urb_complete: bulk urb completed status=0
> length=4096/4096 pack_num=0 errors=0
> [137754.696240] usb 1-3: usb_urb_complete: bulk urb completed status=0
> length=4096/4096 pack_num=0 errors=0
> [137754.697483] usb 1-3: usb_urb_complete: bulk urb completed status=0
> length=4096/4096 pack_num=0 errors=0
> [137754.699002] usb 1-3: usb_urb_complete: bulk urb completed status=0
> length=4096/4096 pack_num=0 errors=0
> [137754.700884] usb 1-3: usb_urb_complete: bulk urb completed status=0
> length=4096/4096 pack_num=0 errors=0
> [137754.701613] usb 1-3: usb_urb_complete: bulk urb completed status=0
> length=4096/4096 pack_num=0 errors=0
> [137754.702986] usb 1-3: usb_urb_complete: bulk urb completed status=0
> length=4096/4096 pack_num=0 errors=0
> [137759.695906] usb_urb_complete: 3595 callbacks suppressed
> [137759.695934] usb 1-3: usb_urb_complete: bulk urb completed status=0
> length=4096/4096 pack_num=0 errors=0
> [137759.697788] usb 1-3: usb_urb_complete: bulk urb completed status=0
> length=4096/4096 pack_num=0 errors=0
> [137759.698772] usb 1-3: usb_urb_complete: bulk urb completed status=0
> length=4096/4096 pack_num=0 errors=0
>
> with -p
>
> [137814.730303] usb_urb_complete: 3555 callbacks suppressed
> [137819.740698] usb_urb_complete: 3519 callbacks suppressed
> [137824.744857] usb_urb_complete: 3443 callbacks suppressed
> [137829.746023] usb_urb_complete: 3345 callbacks suppressed
> [137834.749931] usb_urb_complete: 3558 callbacks suppressed
> [137839.753102] usb_urb_complete: 3465 callbacks suppressed
> [137844.755521] usb_urb_complete: 3438 callbacks suppressed

I think you are using media_build.git (with my devel tree)? Could that 
be due to that as there is some compat stuff? I am not very familiar 
with media_build.git...

regards
Antti

-- 
http://palosaari.fi/

Re: [PATCH 1/1] driver-core: Shut up dev_dbg_reatelimited() without DEBUG

[Hin-Tak Leung]

--- On Wed, 22/8/12, Antti Palosaari <crope-X3B1VOXEql0@public.gmane.org> wrote:

> On 08/22/2012 04:57 PM, Hin-Tak Leung
> wrote:
> > Antti Palosaari wrote:
> >> Hello Hiroshi,
> >>
> >> On 08/21/2012 10:02 AM, Hiroshi Doyu wrote:
> >>> Antti Palosaari <crope-X3B1VOXEql0@public.gmane.org>
> wrote @ Mon, 20 Aug 2012 23:29:34 +0200:
> >>>
> >>>> On 08/20/2012 02:14 PM, Hiroshi Doyu
> wrote:
> >>>>> Hi Antti,
> >>>>>
> >>>>> Antti Palosaari <crope-X3B1VOXEql0@public.gmane.org>
> wrote @ Sat, 18 Aug 2012 02:11:56
> >>>>> +0200:
> >>>>>
> >>>>>> On 08/17/2012 09:04 AM, Hiroshi
> Doyu wrote:
> >>>>>>> dev_dbg_reatelimited() without
> DEBUG printed "217078 callbacks
> >>>>>>> suppressed". This shouldn't
> print anything without DEBUG.
> >>>>>>>
> >>>>>>> Signed-off-by: Hiroshi Doyu
> <hdoyu-DDmLM1+adcrQT0dZR+AlfA@public.gmane.org>
> >>>>>>> Reported-by: Antti Palosaari
> <crope-X3B1VOXEql0@public.gmane.org>
> >>>>>>> ---
> >>>>>>> 
>    include/linux/device.h |    6
> +++++-
> >>>>>>>     1 files
> changed, 5 insertions(+), 1 deletions(-)
> >>>>>>>
> >>>>>>> diff --git
> a/include/linux/device.h b/include/linux/device.h
> >>>>>>> index eb945e1..d4dc26e 100644
> >>>>>>> --- a/include/linux/device.h
> >>>>>>> +++ b/include/linux/device.h
> >>>>>>> @@ -962,9 +962,13 @@ do { 
>                
>                
>   \
> >>>>>>>     
>    dev_level_ratelimited(dev_notice, dev,
> fmt, ##__VA_ARGS__)
> >>>>>>>     #define
> dev_info_ratelimited(dev, fmt, ...)     
>           \
> >>>>>>>     
>    dev_level_ratelimited(dev_info, dev, fmt,
> ##__VA_ARGS__)
> >>>>>>> +#if defined(DEBUG)
> >>>>>>>     #define
> dev_dbg_ratelimited(dev, fmt, ...)     
>           \
> >>>>>>>     
>    dev_level_ratelimited(dev_dbg, dev, fmt,
> ##__VA_ARGS__)
> >>>>>>> -
> >>>>>>> +#else
> >>>>>>> +#define
> dev_dbg_ratelimited(dev, fmt, ...)     
>       \
> >>>>>>> +   
> no_printk(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__)
> >>>>>>> +#endif
> >>>>>>>     /*
> >>>>>>>      * Stupid
> hackaround for existing uses of non-printk uses
> >>>>>>> dev_info
> >>>>>>>      *
> >>>>>>>
> >>>>>>
> >>>>>> NACK. I don't think that's correct
> behavior. After that patch it
> >>>>>> kills
> >>>>>> all output of
> dev_dbg_ratelimited(). If I use dynamic debugs and
> >>>>>> order
> >>>>>> debugs, I expect to see debugs as
> earlier.
> >>>>>
> >>>>> You are right. I attached the update
> patch, just moving *_ratelimited
> >>>>> functions after dev_dbg() definitions.
> >>>>>
> >>>>> With DEBUG defined/undefined in your
> "test.ko", it works fine. With
> >>>>> CONFIG_DYNAMIC_DEBUG, it works with
> "+p", but with "-p", still
> >>>>> "..callbacks suppressed" is printed.
> >>>>
> >>>> I am using dynamic debugs and behavior is
> now just same as it was when
> >>>> reported that bug. OK, likely for static
> debug it is now correct.
> >>>
> >>> The following patch can also refrain
> "..callbacks suppressed" with
> >>> "-p". I think that it's ok for all cases.
> >>>
> >>>> From
> b4c6aa9160f03b61ed17975c73db36c983a48927 Mon Sep 17 00:00:00
> 2001
> >>> From: Hiroshi Doyu <hdoyu-DDmLM1+adcrQT0dZR+AlfA@public.gmane.org>
> >>> Date: Mon, 20 Aug 2012 13:49:19 +0300
> >>> Subject: [v3 1/1] driver-core: Shut up
> dev_dbg_reatelimited() without
> >>> DEBUG
> >>>
> >>> dev_dbg_reatelimited() without DEBUG printed
> "217078 callbacks
> >>> suppressed". This shouldn't print anything
> without DEBUG.
> >>>
> >>> With CONFIG_DYNAMIC_DEBUG, the print should be
> configured as expected.
> >>>
> >>> Signed-off-by: Hiroshi Doyu <hdoyu-DDmLM1+adcrQT0dZR+AlfA@public.gmane.org>
> >>> Reported-by: Antti Palosaari <crope-X3B1VOXEql0@public.gmane.org>
> >>> ---
> >>>   include/linux/device.h
> |   62
> >>>
> +++++++++++++++++++++++++++++------------------
> >>>   1 files changed, 38
> insertions(+), 24 deletions(-)
> >>>
> >>> diff --git a/include/linux/device.h
> b/include/linux/device.h
> >>> index 9648331..bb6ffcb 100644
> >>> --- a/include/linux/device.h
> >>> +++ b/include/linux/device.h
> >>> @@ -932,6 +932,32 @@ int _dev_info(const struct
> device *dev, const
> >>> char *fmt,
> >>> ...)
> >>>
> >>>   #endif
> >>>
> >>> +/*
> >>> + * Stupid hackaround for existing uses of
> non-printk uses dev_info
> >>> + *
> >>> + * Note that the definition of dev_info below
> is actually _dev_info
> >>> + * and a macro is used to avoid redefining
> dev_info
> >>> + */
> >>> +
> >>> +#define dev_info(dev, fmt, arg...)
> _dev_info(dev, fmt, ##arg)
> >>> +
> >>> +#if defined(CONFIG_DYNAMIC_DEBUG)
> >>> +#define dev_dbg(dev, format, ...)   
>          \
> >>> +do {           
>              
>    \
> >>> +    dynamic_dev_dbg(dev, format,
> ##__VA_ARGS__); \
> >>> +} while (0)
> >>> +#elif defined(DEBUG)
> >>> +#define dev_dbg(dev, format, arg...) 
>       \
> >>> +    dev_printk(KERN_DEBUG, dev,
> format, ##arg)
> >>> +#else
> >>> +#define dev_dbg(dev, format, arg...) 
>               \
> >>> +({           
>                
>     \
> >>> +    if (0)     
>                
>       \
> >>> +       
> dev_printk(KERN_DEBUG, dev, format, ##arg);    \
> >>> +    0;       
>                
>     \
> >>> +})
> >>> +#endif
> >>> +
> >>>   #define
> dev_level_ratelimited(dev_level, dev, fmt, ...)   
>         \
> >>>   do {     
>                
>               \
> >>>       static
> DEFINE_RATELIMIT_STATE(_rs,       
>         \
> >>> @@ -955,33 +981,21 @@ do {     
>                
>               \
> >>>   
>    dev_level_ratelimited(dev_notice, dev,
> fmt, ##__VA_ARGS__)
> >>>   #define
> dev_info_ratelimited(dev, fmt, ...)     
>           \
> >>>   
>    dev_level_ratelimited(dev_info, dev, fmt,
> ##__VA_ARGS__)
> >>> +#if defined(CONFIG_DYNAMIC_DEBUG) ||
> defined(DEBUG)
> >>>   #define
> dev_dbg_ratelimited(dev, fmt, ...)     
>           \
> >>> -    dev_level_ratelimited(dev_dbg,
> dev, fmt, ##__VA_ARGS__)
> >>> -
> >>> -/*
> >>> - * Stupid hackaround for existing uses of
> non-printk uses dev_info
> >>> - *
> >>> - * Note that the definition of dev_info below
> is actually _dev_info
> >>> - * and a macro is used to avoid redefining
> dev_info
> >>> - */
> >>> -
> >>> -#define dev_info(dev, fmt, arg...)
> _dev_info(dev, fmt, ##arg)
> >>> -
> >>> -#if defined(CONFIG_DYNAMIC_DEBUG)
> >>> -#define dev_dbg(dev, format, ...)   
>          \
> >>> -do {           
>              
>    \
> >>> -    dynamic_dev_dbg(dev, format,
> ##__VA_ARGS__); \
> >>> +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, pr_fmt(fmt), 
>       \
> >>> +           
>        ##__VA_ARGS__);   
>         \
> >>>   } while (0)
> >>> -#elif defined(DEBUG)
> >>> -#define dev_dbg(dev, format, arg...) 
>       \
> >>> -    dev_printk(KERN_DEBUG, dev,
> format, ##arg)
> >>>   #else
> >>> -#define dev_dbg(dev, format, arg...) 
>               \
> >>> -({           
>                
>     \
> >>> -    if (0)     
>                
>       \
> >>> -       
> dev_printk(KERN_DEBUG, dev, format, ##arg);    \
> >>> -    0;       
>                
>     \
> >>> -})
> >>> +#define dev_dbg_ratelimited(dev, fmt,
> ...)            \
> >>> +    no_printk(KERN_DEBUG
> pr_fmt(fmt), ##__VA_ARGS__)
> >>>   #endif
> >>>
> >>>   #ifdef VERBOSE_DEBUG
> >>
> >> That seems to work correctly now. I tested it using
> dynamic debugs. It
> >> was
> >> Hin-Tak who originally reported that bug for me
> after I added few
> >> ratelimited
> >> debugs for DVB stack. Thank you!
> >>
> >> Reported-by: Hin-Tak Leung <htl10-Rn4VEauK+AKRv+LV9MX5uipxlwaOVQ5f@public.gmane.org>
> >> Tested-by: Antti Palosaari <crope-X3B1VOXEql0@public.gmane.org>
> >>
> >>
> >> regards
> >> Antti
> >>
> >
> > This is with mediatree/for_v3.7-8 , playing DVB-T video
> with mplayer.
> >
> > echo 'file ...media_build/v4l/usb_urb.c +p' >
> > /sys/kernel/debug/dynamic_debug/control
> >
> > With +p
> >
> > [137749.698202] usb 1-3: usb_urb_complete: bulk urb
> completed status=0
> > length=4096/4096 pack_num=0 errors=0
> > [137749.699449] usb 1-3: usb_urb_complete: bulk urb
> completed status=0
> > length=4096/4096 pack_num=0 errors=0
> > [137749.700825] usb 1-3: usb_urb_complete: bulk urb
> completed status=0
> > length=4096/4096 pack_num=0 errors=0
> > [137754.690862] usb_urb_complete: 3570 callbacks
> suppressed
> > [137754.690888] usb 1-3: usb_urb_complete: bulk urb
> completed status=0
> > length=4096/4096 pack_num=0 errors=0
> > [137754.692489] usb 1-3: usb_urb_complete: bulk urb
> completed status=0
> > length=4096/4096 pack_num=0 errors=0
> > [137754.693745] usb 1-3: usb_urb_complete: bulk urb
> completed status=0
> > length=4096/4096 pack_num=0 errors=0
> > [137754.694882] usb 1-3: usb_urb_complete: bulk urb
> completed status=0
> > length=4096/4096 pack_num=0 errors=0
> > [137754.696240] usb 1-3: usb_urb_complete: bulk urb
> completed status=0
> > length=4096/4096 pack_num=0 errors=0
> > [137754.697483] usb 1-3: usb_urb_complete: bulk urb
> completed status=0
> > length=4096/4096 pack_num=0 errors=0
> > [137754.699002] usb 1-3: usb_urb_complete: bulk urb
> completed status=0
> > length=4096/4096 pack_num=0 errors=0
> > [137754.700884] usb 1-3: usb_urb_complete: bulk urb
> completed status=0
> > length=4096/4096 pack_num=0 errors=0
> > [137754.701613] usb 1-3: usb_urb_complete: bulk urb
> completed status=0
> > length=4096/4096 pack_num=0 errors=0
> > [137754.702986] usb 1-3: usb_urb_complete: bulk urb
> completed status=0
> > length=4096/4096 pack_num=0 errors=0
> > [137759.695906] usb_urb_complete: 3595 callbacks
> suppressed
> > [137759.695934] usb 1-3: usb_urb_complete: bulk urb
> completed status=0
> > length=4096/4096 pack_num=0 errors=0
> > [137759.697788] usb 1-3: usb_urb_complete: bulk urb
> completed status=0
> > length=4096/4096 pack_num=0 errors=0
> > [137759.698772] usb 1-3: usb_urb_complete: bulk urb
> completed status=0
> > length=4096/4096 pack_num=0 errors=0
> >
> > with -p
> >
> > [137814.730303] usb_urb_complete: 3555 callbacks
> suppressed
> > [137819.740698] usb_urb_complete: 3519 callbacks
> suppressed
> > [137824.744857] usb_urb_complete: 3443 callbacks
> suppressed
> > [137829.746023] usb_urb_complete: 3345 callbacks
> suppressed
> > [137834.749931] usb_urb_complete: 3558 callbacks
> suppressed
> > [137839.753102] usb_urb_complete: 3465 callbacks
> suppressed
> > [137844.755521] usb_urb_complete: 3438 callbacks
> suppressed
> 
> I think you are using media_build.git (with my devel tree)?
> Could that 
> be due to that as there is some compat stuff? I am not very
> familiar 
> with media_build.git...

Acked-by: Hin-Tak Leung <htl10-Rn4VEauK+AKRv+LV9MX5uipxlwaOVQ5f@public.gmane.org>
Reported-by: Hin-Tak Leung <htl10-Rn4VEauK+AKRv+LV9MX5uipxlwaOVQ5f@public.gmane.org>

Yes, sorry about that. media_build is picking up the system's kernel header, I think - dev_dbg_ratelimited is defined in the older kernel 3.5.x's include/linux/device.h .

Yes, it was me who first noticed the problem (when DVB-usb started using the define).