diff mbox

[RFC,2/6] wifi: Don't spam logs with 'Found new beacon' messages.

Message ID 1355349295-30960-2-git-send-email-greearb@candelatech.com (mailing list archive)
State Not Applicable, archived
Headers show

Commit Message

Ben Greear Dec. 12, 2012, 9:54 p.m. UTC
From: Ben Greear <greearb@candelatech.com>

We saw logs fill with this (at very high speeds):

cfg80211: Found new beacon on frequency: 5745 MHz (Ch 149) on wiphy0
cfg80211: Found new beacon on frequency: 5745 MHz (Ch 149) on wiphy0
cfg80211: Found new beacon on frequency: 5745 MHz (Ch 149) on wiphy0
cfg80211: Found new beacon on frequency: 5745 MHz (Ch 149) on wiphy0
cfg80211: Found new beacon on frequency: 5745 MHz (Ch 149) on wiphy0
cfg80211: Found new beacon on frequency: 5745 MHz (Ch 149) on wiphy0
cfg80211: Found new beacon on frequency: 5745 MHz (Ch 149) on wiphy0
cfg80211: Found new beacon on frequency: 5745 MHz (Ch 149) on wiphy0
cfg80211: Found new beacon on frequency: 5745 MHz (Ch 149) on wiphy0
cfg80211: Found new beacon on frequency: 5745 MHz (Ch 149) on wiphy0
cfg80211: Found new beacon on frequency: 5745 MHz (Ch 149) on wiphy0
cfg80211: Found new beacon on frequency: 5745 MHz (Ch 149) on wiphy0

Signed-off-by: Ben Greear <greearb@candelatech.com>
---
 net/wireless/reg.c |   11 ++++++-----
 1 files changed, 6 insertions(+), 5 deletions(-)

Comments

Johannes Berg Dec. 12, 2012, 10:08 p.m. UTC | #1
On Wed, 2012-12-12 at 13:54 -0800, greearb@candelatech.com wrote:
> From: Ben Greear <greearb@candelatech.com>
> 
> We saw logs fill with this (at very high speeds):
> 
> cfg80211: Found new beacon on frequency: 5745 MHz (Ch 149) on wiphy0
> cfg80211: Found new beacon on frequency: 5745 MHz (Ch 149) on wiphy0
> cfg80211: Found new beacon on frequency: 5745 MHz (Ch 149) on wiphy0
> cfg80211: Found new beacon on frequency: 5745 MHz (Ch 149) on wiphy0
> cfg80211: Found new beacon on frequency: 5745 MHz (Ch 149) on wiphy0
> cfg80211: Found new beacon on frequency: 5745 MHz (Ch 149) on wiphy0
> cfg80211: Found new beacon on frequency: 5745 MHz (Ch 149) on wiphy0
> cfg80211: Found new beacon on frequency: 5745 MHz (Ch 149) on wiphy0
> cfg80211: Found new beacon on frequency: 5745 MHz (Ch 149) on wiphy0
> cfg80211: Found new beacon on frequency: 5745 MHz (Ch 149) on wiphy0
> cfg80211: Found new beacon on frequency: 5745 MHz (Ch 149) on wiphy0
> cfg80211: Found new beacon on frequency: 5745 MHz (Ch 149) on wiphy0
> 
> Signed-off-by: Ben Greear <greearb@candelatech.com>
> ---
>  net/wireless/reg.c |   11 ++++++-----
>  1 files changed, 6 insertions(+), 5 deletions(-)
> 
> diff --git a/net/wireless/reg.c b/net/wireless/reg.c
> index 6e53089..8aa7867 100644
> --- a/net/wireless/reg.c
> +++ b/net/wireless/reg.c
> @@ -2067,11 +2067,12 @@ int regulatory_hint_found_beacon(struct wiphy *wiphy,
>  	if (!reg_beacon)
>  		return -ENOMEM;
>  
> -	REG_DBG_PRINT("Found new beacon on "

Why not just disable the config option for it if you don't care?

johannes

--
To unsubscribe from this list: send the line "unsubscribe linux-wireless" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Ben Greear Dec. 12, 2012, 10:15 p.m. UTC | #2
On 12/12/2012 02:08 PM, Johannes Berg wrote:
> On Wed, 2012-12-12 at 13:54 -0800, greearb@candelatech.com wrote:
>> From: Ben Greear <greearb@candelatech.com>
>>
>> We saw logs fill with this (at very high speeds):
>>
>> cfg80211: Found new beacon on frequency: 5745 MHz (Ch 149) on wiphy0
>> cfg80211: Found new beacon on frequency: 5745 MHz (Ch 149) on wiphy0
>> cfg80211: Found new beacon on frequency: 5745 MHz (Ch 149) on wiphy0
>> cfg80211: Found new beacon on frequency: 5745 MHz (Ch 149) on wiphy0
>> cfg80211: Found new beacon on frequency: 5745 MHz (Ch 149) on wiphy0
>> cfg80211: Found new beacon on frequency: 5745 MHz (Ch 149) on wiphy0
>> cfg80211: Found new beacon on frequency: 5745 MHz (Ch 149) on wiphy0
>> cfg80211: Found new beacon on frequency: 5745 MHz (Ch 149) on wiphy0
>> cfg80211: Found new beacon on frequency: 5745 MHz (Ch 149) on wiphy0
>> cfg80211: Found new beacon on frequency: 5745 MHz (Ch 149) on wiphy0
>> cfg80211: Found new beacon on frequency: 5745 MHz (Ch 149) on wiphy0
>> cfg80211: Found new beacon on frequency: 5745 MHz (Ch 149) on wiphy0
>>
>> Signed-off-by: Ben Greear <greearb@candelatech.com>
>> ---
>>   net/wireless/reg.c |   11 ++++++-----
>>   1 files changed, 6 insertions(+), 5 deletions(-)
>>
>> diff --git a/net/wireless/reg.c b/net/wireless/reg.c
>> index 6e53089..8aa7867 100644
>> --- a/net/wireless/reg.c
>> +++ b/net/wireless/reg.c
>> @@ -2067,11 +2067,12 @@ int regulatory_hint_found_beacon(struct wiphy *wiphy,
>>   	if (!reg_beacon)
>>   		return -ENOMEM;
>>
>> -	REG_DBG_PRINT("Found new beacon on "
>
> Why not just disable the config option for it if you don't care?

I don't mind seeing it, just don't want thousands of them in my logs
in a very short amount of time.  Maybe I was just hitting some
other bug, and there is no valid reason for this to ever spam?

Thanks,
Ben

>
> johannes
>
Johannes Berg Dec. 12, 2012, 10:17 p.m. UTC | #3
On Wed, 2012-12-12 at 14:15 -0800, Ben Greear wrote:
> On 12/12/2012 02:08 PM, Johannes Berg wrote:
> > On Wed, 2012-12-12 at 13:54 -0800, greearb@candelatech.com wrote:
> >> From: Ben Greear <greearb@candelatech.com>
> >>
> >> We saw logs fill with this (at very high speeds):
> >>
> >> cfg80211: Found new beacon on frequency: 5745 MHz (Ch 149) on wiphy0
> >> cfg80211: Found new beacon on frequency: 5745 MHz (Ch 149) on wiphy0
> >> cfg80211: Found new beacon on frequency: 5745 MHz (Ch 149) on wiphy0
> >> cfg80211: Found new beacon on frequency: 5745 MHz (Ch 149) on wiphy0
> >> cfg80211: Found new beacon on frequency: 5745 MHz (Ch 149) on wiphy0
> >> cfg80211: Found new beacon on frequency: 5745 MHz (Ch 149) on wiphy0
> >> cfg80211: Found new beacon on frequency: 5745 MHz (Ch 149) on wiphy0
> >> cfg80211: Found new beacon on frequency: 5745 MHz (Ch 149) on wiphy0
> >> cfg80211: Found new beacon on frequency: 5745 MHz (Ch 149) on wiphy0
> >> cfg80211: Found new beacon on frequency: 5745 MHz (Ch 149) on wiphy0
> >> cfg80211: Found new beacon on frequency: 5745 MHz (Ch 149) on wiphy0
> >> cfg80211: Found new beacon on frequency: 5745 MHz (Ch 149) on wiphy0
> >>
> >> Signed-off-by: Ben Greear <greearb@candelatech.com>
> >> ---
> >>   net/wireless/reg.c |   11 ++++++-----
> >>   1 files changed, 6 insertions(+), 5 deletions(-)
> >>
> >> diff --git a/net/wireless/reg.c b/net/wireless/reg.c
> >> index 6e53089..8aa7867 100644
> >> --- a/net/wireless/reg.c
> >> +++ b/net/wireless/reg.c
> >> @@ -2067,11 +2067,12 @@ int regulatory_hint_found_beacon(struct wiphy *wiphy,
> >>   	if (!reg_beacon)
> >>   		return -ENOMEM;
> >>
> >> -	REG_DBG_PRINT("Found new beacon on "
> >
> > Why not just disable the config option for it if you don't care?
> 
> I don't mind seeing it, just don't want thousands of them in my logs
> in a very short amount of time.  Maybe I was just hitting some
> other bug, and there is no valid reason for this to ever spam?

Quite likely, since I think it's supposed to happen only once for each
channel unless you reset the regulatory (but that would cause more
messages? I think?)

johannes

--
To unsubscribe from this list: send the line "unsubscribe linux-wireless" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Johannes Berg Dec. 12, 2012, 10:20 p.m. UTC | #4
On Wed, 2012-12-12 at 23:17 +0100, Johannes Berg wrote:
> On Wed, 2012-12-12 at 14:15 -0800, Ben Greear wrote:
> > On 12/12/2012 02:08 PM, Johannes Berg wrote:
> > > On Wed, 2012-12-12 at 13:54 -0800, greearb@candelatech.com wrote:
> > >> From: Ben Greear <greearb@candelatech.com>
> > >>
> > >> We saw logs fill with this (at very high speeds):
> > >>
> > >> cfg80211: Found new beacon on frequency: 5745 MHz (Ch 149) on wiphy0
> > >> cfg80211: Found new beacon on frequency: 5745 MHz (Ch 149) on wiphy0
> > >> cfg80211: Found new beacon on frequency: 5745 MHz (Ch 149) on wiphy0
> > >> cfg80211: Found new beacon on frequency: 5745 MHz (Ch 149) on wiphy0
> > >> cfg80211: Found new beacon on frequency: 5745 MHz (Ch 149) on wiphy0
> > >> cfg80211: Found new beacon on frequency: 5745 MHz (Ch 149) on wiphy0
> > >> cfg80211: Found new beacon on frequency: 5745 MHz (Ch 149) on wiphy0
> > >> cfg80211: Found new beacon on frequency: 5745 MHz (Ch 149) on wiphy0
> > >> cfg80211: Found new beacon on frequency: 5745 MHz (Ch 149) on wiphy0
> > >> cfg80211: Found new beacon on frequency: 5745 MHz (Ch 149) on wiphy0
> > >> cfg80211: Found new beacon on frequency: 5745 MHz (Ch 149) on wiphy0
> > >> cfg80211: Found new beacon on frequency: 5745 MHz (Ch 149) on wiphy0
> > >>
> > >> Signed-off-by: Ben Greear <greearb@candelatech.com>
> > >> ---
> > >>   net/wireless/reg.c |   11 ++++++-----
> > >>   1 files changed, 6 insertions(+), 5 deletions(-)
> > >>
> > >> diff --git a/net/wireless/reg.c b/net/wireless/reg.c
> > >> index 6e53089..8aa7867 100644
> > >> --- a/net/wireless/reg.c
> > >> +++ b/net/wireless/reg.c
> > >> @@ -2067,11 +2067,12 @@ int regulatory_hint_found_beacon(struct wiphy *wiphy,
> > >>   	if (!reg_beacon)
> > >>   		return -ENOMEM;
> > >>
> > >> -	REG_DBG_PRINT("Found new beacon on "
> > >
> > > Why not just disable the config option for it if you don't care?
> > 
> > I don't mind seeing it, just don't want thousands of them in my logs
> > in a very short amount of time.  Maybe I was just hitting some
> > other bug, and there is no valid reason for this to ever spam?
> 
> Quite likely, since I think it's supposed to happen only once for each
> channel unless you reset the regulatory (but that would cause more
> messages? I think?)

Ah, no, I get it. It is related to your many interfaces :-)

The thing is that when a beacon comes in it schedules a work item, and
that work item only sets the beacon_found to true. Now since you have a
ton of interfaces each beacon can be processed many times, and you get a
ton of work items, and ... ouch.

Not sure how the locking works here so can't really suggest a fix right
now.

johannes

--
To unsubscribe from this list: send the line "unsubscribe linux-wireless" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Johannes Berg Dec. 12, 2012, 10:24 p.m. UTC | #5
On Wed, 2012-12-12 at 23:20 +0100, Johannes Berg wrote:
> On Wed, 2012-12-12 at 23:17 +0100, Johannes Berg wrote:
> > On Wed, 2012-12-12 at 14:15 -0800, Ben Greear wrote:
> > > On 12/12/2012 02:08 PM, Johannes Berg wrote:
> > > > On Wed, 2012-12-12 at 13:54 -0800, greearb@candelatech.com wrote:
> > > >> From: Ben Greear <greearb@candelatech.com>
> > > >>
> > > >> We saw logs fill with this (at very high speeds):
> > > >>
> > > >> cfg80211: Found new beacon on frequency: 5745 MHz (Ch 149) on wiphy0
> > > >> cfg80211: Found new beacon on frequency: 5745 MHz (Ch 149) on wiphy0
> > > >> cfg80211: Found new beacon on frequency: 5745 MHz (Ch 149) on wiphy0
> > > >> cfg80211: Found new beacon on frequency: 5745 MHz (Ch 149) on wiphy0
> > > >> cfg80211: Found new beacon on frequency: 5745 MHz (Ch 149) on wiphy0
> > > >> cfg80211: Found new beacon on frequency: 5745 MHz (Ch 149) on wiphy0
> > > >> cfg80211: Found new beacon on frequency: 5745 MHz (Ch 149) on wiphy0
> > > >> cfg80211: Found new beacon on frequency: 5745 MHz (Ch 149) on wiphy0
> > > >> cfg80211: Found new beacon on frequency: 5745 MHz (Ch 149) on wiphy0
> > > >> cfg80211: Found new beacon on frequency: 5745 MHz (Ch 149) on wiphy0
> > > >> cfg80211: Found new beacon on frequency: 5745 MHz (Ch 149) on wiphy0
> > > >> cfg80211: Found new beacon on frequency: 5745 MHz (Ch 149) on wiphy0
> > > >>
> > > >> Signed-off-by: Ben Greear <greearb@candelatech.com>
> > > >> ---
> > > >>   net/wireless/reg.c |   11 ++++++-----
> > > >>   1 files changed, 6 insertions(+), 5 deletions(-)
> > > >>
> > > >> diff --git a/net/wireless/reg.c b/net/wireless/reg.c
> > > >> index 6e53089..8aa7867 100644
> > > >> --- a/net/wireless/reg.c
> > > >> +++ b/net/wireless/reg.c
> > > >> @@ -2067,11 +2067,12 @@ int regulatory_hint_found_beacon(struct wiphy *wiphy,
> > > >>   	if (!reg_beacon)
> > > >>   		return -ENOMEM;
> > > >>
> > > >> -	REG_DBG_PRINT("Found new beacon on "
> > > >
> > > > Why not just disable the config option for it if you don't care?
> > > 
> > > I don't mind seeing it, just don't want thousands of them in my logs
> > > in a very short amount of time.  Maybe I was just hitting some
> > > other bug, and there is no valid reason for this to ever spam?
> > 
> > Quite likely, since I think it's supposed to happen only once for each
> > channel unless you reset the regulatory (but that would cause more
> > messages? I think?)
> 
> Ah, no, I get it. It is related to your many interfaces :-)
> 
> The thing is that when a beacon comes in it schedules a work item, and
> that work item only sets the beacon_found to true. Now since you have a
> ton of interfaces each beacon can be processed many times, and you get a
> ton of work items, and ... ouch.

Or if you're not world roaming.. this is really bad, we alloc all those
beacon hint structs just to not do anything with them, I wonder if they
even get leaked or added to reg_beacon_list (but that's about the same)

This is pretty much a mess. Luis?

johannes

--
To unsubscribe from this list: send the line "unsubscribe linux-wireless" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Luis R. Rodriguez Dec. 13, 2012, 8:31 p.m. UTC | #6
On Wed, Dec 12, 2012 at 11:24:27PM +0100, Johannes Berg wrote:
> On Wed, 2012-12-12 at 23:20 +0100, Johannes Berg wrote:
> > On Wed, 2012-12-12 at 23:17 +0100, Johannes Berg wrote:
> > > On Wed, 2012-12-12 at 14:15 -0800, Ben Greear wrote:
> > > > On 12/12/2012 02:08 PM, Johannes Berg wrote:
> > > > > On Wed, 2012-12-12 at 13:54 -0800, greearb@candelatech.com wrote:
> > > > >> From: Ben Greear <greearb@candelatech.com>
> > > > >>
> > > > >> We saw logs fill with this (at very high speeds):
> > > > >>
> > > > >> cfg80211: Found new beacon on frequency: 5745 MHz (Ch 149) on wiphy0
> > > > >> cfg80211: Found new beacon on frequency: 5745 MHz (Ch 149) on wiphy0
> > > > >> cfg80211: Found new beacon on frequency: 5745 MHz (Ch 149) on wiphy0
> > > > >> cfg80211: Found new beacon on frequency: 5745 MHz (Ch 149) on wiphy0
> > > > >> cfg80211: Found new beacon on frequency: 5745 MHz (Ch 149) on wiphy0
> > > > >> cfg80211: Found new beacon on frequency: 5745 MHz (Ch 149) on wiphy0
> > > > >> cfg80211: Found new beacon on frequency: 5745 MHz (Ch 149) on wiphy0
> > > > >> cfg80211: Found new beacon on frequency: 5745 MHz (Ch 149) on wiphy0
> > > > >> cfg80211: Found new beacon on frequency: 5745 MHz (Ch 149) on wiphy0
> > > > >> cfg80211: Found new beacon on frequency: 5745 MHz (Ch 149) on wiphy0
> > > > >> cfg80211: Found new beacon on frequency: 5745 MHz (Ch 149) on wiphy0
> > > > >> cfg80211: Found new beacon on frequency: 5745 MHz (Ch 149) on wiphy0
> > > > >>
> > > > >> Signed-off-by: Ben Greear <greearb@candelatech.com>
> > > > >> ---
> > > > >>   net/wireless/reg.c |   11 ++++++-----
> > > > >>   1 files changed, 6 insertions(+), 5 deletions(-)
> > > > >>
> > > > >> diff --git a/net/wireless/reg.c b/net/wireless/reg.c
> > > > >> index 6e53089..8aa7867 100644
> > > > >> --- a/net/wireless/reg.c
> > > > >> +++ b/net/wireless/reg.c
> > > > >> @@ -2067,11 +2067,12 @@ int regulatory_hint_found_beacon(struct wiphy *wiphy,
> > > > >>   	if (!reg_beacon)
> > > > >>   		return -ENOMEM;
> > > > >>
> > > > >> -	REG_DBG_PRINT("Found new beacon on "
> > > > >
> > > > > Why not just disable the config option for it if you don't care?
> > > > 
> > > > I don't mind seeing it, just don't want thousands of them in my logs
> > > > in a very short amount of time.  Maybe I was just hitting some
> > > > other bug, and there is no valid reason for this to ever spam?
> > > 
> > > Quite likely, since I think it's supposed to happen only once for each
> > > channel unless you reset the regulatory (but that would cause more
> > > messages? I think?)
> > 
> > Ah, no, I get it. It is related to your many interfaces :-)
> > 
> > The thing is that when a beacon comes in it schedules a work item, and
> > that work item only sets the beacon_found to true. Now since you have a
> > ton of interfaces each beacon can be processed many times, and you get a
> > ton of work items, and ... ouch.

As explained below indeed you should only see this once for one channel
even if your box has a billion interfaces, but Johannes is right that we
won't be able to reap benefits of the check that annotates this was an
already established beacon hint until the work item gets processed and
since its a scheduled task we can potentially alloc quite a lot of beacon
hints for the same channel if you have a lot of interfaces.

I'll post a patch for this, please test.

> Or if you're not world roaming.. this is really bad, we alloc all those
> beacon hint structs just to not do anything with them,

Indeed, we don't annotate the beacon hint as found if we are not world
roaming. I'll look to annotate this, patch to follow after the first one.

> I wonder if they even get leaked or added to reg_beacon_list (but that's
> about the same)

We get beacon hints added to the reg_beacon_list if the channel fits
the area where we allow it given that we allow for future devices to
pop up and we want them to learn from the exisitng device's information.
We can certainly change this if we want.

  Luis
--
To unsubscribe from this list: send the line "unsubscribe linux-wireless" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
diff mbox

Patch

diff --git a/net/wireless/reg.c b/net/wireless/reg.c
index 6e53089..8aa7867 100644
--- a/net/wireless/reg.c
+++ b/net/wireless/reg.c
@@ -2067,11 +2067,12 @@  int regulatory_hint_found_beacon(struct wiphy *wiphy,
 	if (!reg_beacon)
 		return -ENOMEM;
 
-	REG_DBG_PRINT("Found new beacon on "
-		      "frequency: %d MHz (Ch %d) on %s\n",
-		      beacon_chan->center_freq,
-		      ieee80211_frequency_to_channel(beacon_chan->center_freq),
-		      wiphy_name(wiphy));
+	if (printk_ratelimit())
+		REG_DBG_PRINT("Found new beacon on "
+			      "frequency: %d MHz (Ch %d) on %s\n",
+			      beacon_chan->center_freq,
+			      ieee80211_frequency_to_channel(beacon_chan->center_freq),
+			      wiphy_name(wiphy));
 
 	memcpy(&reg_beacon->chan, beacon_chan,
 		sizeof(struct ieee80211_channel));