[PATCH] Prevent printk ratelimiting from spamming kernel log while DEBUG not defined

[PATCH] Prevent printk ratelimiting from spamming kernel log while DEBUG not defined

[Sander Eikelenboom]

Hi All,

This patch is for USB sound, but the construction is widely used in the kernel,
so this could pop up in more places.

Greg, Julia,

Would it be worthwhile to sweep this tree wide ?
And would this be something for Coccinelle ?
This probably also goes for the other loglevels and the "net" variant.


Sander Eikelenboom (1):
  Sound USB: Prevent printk ratelimiting from spamming kernel log while
    DEBUG not defined

 sound/usb/pcm.c |    5 ++---
 1 file changed, 2 insertions(+), 3 deletions(-)

-- 
1.7.10.4

[PATCH] Sound USB: Prevent printk ratelimiting from spamming kernel log while DEBUG not defined

[Sander Eikelenboom]

This (widely used) construction:

if(printk_ratelimit())
	dev_dbg()

Causes the ratelimiting to spam the kernel log with the "callbacks suppressed"
message below, even while the dev_dbg it is supposed to rate limit wouldn't
print anything because DEBUG is not defined for this device.

[  533.803964] retire_playback_urb: 852 callbacks suppressed
[  538.807930] retire_playback_urb: 852 callbacks suppressed
[  543.811897] retire_playback_urb: 852 callbacks suppressed
[  548.815745] retire_playback_urb: 852 callbacks suppressed
[  553.819826] retire_playback_urb: 852 callbacks suppressed

So use dev_dbg_ratelimited() instead of this construction.

Signed-off-by: Sander Eikelenboom <linux@eikelenboom.it>
---
 sound/usb/pcm.c |    5 ++---
 1 file changed, 2 insertions(+), 3 deletions(-)

diff --git a/sound/usb/pcm.c b/sound/usb/pcm.c
index 131336d..c62a165 100644
--- a/sound/usb/pcm.c
+++ b/sound/usb/pcm.c
@@ -1501,9 +1501,8 @@ static void retire_playback_urb(struct snd_usb_substream *subs,
 	 * The error should be lower than 2ms since the estimate relies
 	 * on two reads of a counter updated every ms.
 	 */
-	if (printk_ratelimit() &&
-	    abs(est_delay - subs->last_delay) * 1000 > runtime->rate * 2)
-		dev_dbg(&subs->dev->dev,
+	if (abs(est_delay - subs->last_delay) * 1000 > runtime->rate * 2)
+		dev_dbg_ratelimited(&subs->dev->dev,
 			"delay: estimated %d, actual %d\n",
 			est_delay, subs->last_delay);
 
-- 
1.7.10.4

Re: [PATCH] Sound USB: Prevent printk ratelimiting from spamming kernel log while DEBUG not defined

[Takashi Iwai]

At Fri,  2 May 2014 15:09:27 +0200,
Sander Eikelenboom wrote:
> 
> This (widely used) construction:
> 
> if(printk_ratelimit())
> 	dev_dbg()
> 
> Causes the ratelimiting to spam the kernel log with the "callbacks suppressed"
> message below, even while the dev_dbg it is supposed to rate limit wouldn't
> print anything because DEBUG is not defined for this device.
> 
> [  533.803964] retire_playback_urb: 852 callbacks suppressed
> [  538.807930] retire_playback_urb: 852 callbacks suppressed
> [  543.811897] retire_playback_urb: 852 callbacks suppressed
> [  548.815745] retire_playback_urb: 852 callbacks suppressed
> [  553.819826] retire_playback_urb: 852 callbacks suppressed
> 
> So use dev_dbg_ratelimited() instead of this construction.
> 
> Signed-off-by: Sander Eikelenboom <linux@eikelenboom.it>

Thanks, applied.  This is a result of the recent rewrite to dev_dbg()
from plain printk(), I suppose.


Takashi

> ---
>  sound/usb/pcm.c |    5 ++---
>  1 file changed, 2 insertions(+), 3 deletions(-)
> 
> diff --git a/sound/usb/pcm.c b/sound/usb/pcm.c
> index 131336d..c62a165 100644
> --- a/sound/usb/pcm.c
> +++ b/sound/usb/pcm.c
> @@ -1501,9 +1501,8 @@ static void retire_playback_urb(struct snd_usb_substream *subs,
>  	 * The error should be lower than 2ms since the estimate relies
>  	 * on two reads of a counter updated every ms.
>  	 */
> -	if (printk_ratelimit() &&
> -	    abs(est_delay - subs->last_delay) * 1000 > runtime->rate * 2)
> -		dev_dbg(&subs->dev->dev,
> +	if (abs(est_delay - subs->last_delay) * 1000 > runtime->rate * 2)
> +		dev_dbg_ratelimited(&subs->dev->dev,
>  			"delay: estimated %d, actual %d\n",
>  			est_delay, subs->last_delay);
>  
> -- 
> 1.7.10.4
> 

Re: [PATCH] Sound USB: Prevent printk ratelimiting from spamming kernel log while DEBUG not defined

[Sander Eikelenboom]

Friday, May 2, 2014, 6:13:09 PM, you wrote:

> At Fri,  2 May 2014 15:09:27 +0200,
> Sander Eikelenboom wrote:
>> 
>> This (widely used) construction:
>> 
>> if(printk_ratelimit())
>>       dev_dbg()
>> 
>> Causes the ratelimiting to spam the kernel log with the "callbacks suppressed"
>> message below, even while the dev_dbg it is supposed to rate limit wouldn't
>> print anything because DEBUG is not defined for this device.
>> 
>> [  533.803964] retire_playback_urb: 852 callbacks suppressed
>> [  538.807930] retire_playback_urb: 852 callbacks suppressed
>> [  543.811897] retire_playback_urb: 852 callbacks suppressed
>> [  548.815745] retire_playback_urb: 852 callbacks suppressed
>> [  553.819826] retire_playback_urb: 852 callbacks suppressed
>> 
>> So use dev_dbg_ratelimited() instead of this construction.
>> 
>> Signed-off-by: Sander Eikelenboom <linux@eikelenboom.it>

> Thanks, applied.  This is a result of the recent rewrite to dev_dbg()
> from plain printk(), I suppose.

Yes that patch (https://lkml.org/lkml/2014/4/9/457) prevented spamming the kernel log when debugging was enabled ..
but  now the rate limiting code starts spamming the kernel log instead :-)

I must say i wasn't very aware of that effect either and also used this construction on 
debug patches.


> Takashi

>> ---
>>  sound/usb/pcm.c |    5 ++---
>>  1 file changed, 2 insertions(+), 3 deletions(-)
>> 
>> diff --git a/sound/usb/pcm.c b/sound/usb/pcm.c
>> index 131336d..c62a165 100644
>> --- a/sound/usb/pcm.c
>> +++ b/sound/usb/pcm.c
>> @@ -1501,9 +1501,8 @@ static void retire_playback_urb(struct snd_usb_substream *subs,
>>        * The error should be lower than 2ms since the estimate relies
>>        * on two reads of a counter updated every ms.
>>        */
>> -     if (printk_ratelimit() &&
>> -         abs(est_delay - subs->last_delay) * 1000 > runtime->rate * 2)
>> -             dev_dbg(&subs->dev->dev,
>> +     if (abs(est_delay - subs->last_delay) * 1000 > runtime->rate * 2)
>> +             dev_dbg_ratelimited(&subs->dev->dev,
>>                       "delay: estimated %d, actual %d\n",
>>                       est_delay, subs->last_delay);
>>  
>> -- 
>> 1.7.10.4
>>