RFC: Add precise timing to wifi association messages?

RFC: Add precise timing to wifi association messages?

[Ben Greear]

Any interest in a patch looking similar to that below for the
5 or so messages related to association?  I found it useful for
tracking down why it was taking longer than expected to roam
to a new AP...


diff --git a/net/mac80211/mlme.c b/net/mac80211/mlme.c
index d2510c0..2e96813 100644
--- a/net/mac80211/mlme.c
+++ b/net/mac80211/mlme.c
@@ -908,6 +908,12 @@ static void ieee80211_send_assoc(struct ieee80211_sub_if_data *sdata)
                memcpy(pos, assoc_data->ie + offset, noffset - offset);
        }

+       {
+               struct timeval tv;
+               do_gettimeofday(&tv);
+               sdata_info(sdata, "send_assoc, calling prepare_tx at: %lu.%lu\n",
+                          tv.tv_sec, tv.tv_usec);
+       }
        drv_mgd_prepare_tx(local, sdata);

        IEEE80211_SKB_CB(skb)->flags |= IEEE80211_TX_INTFL_DONT_ENCRYPT;


Thanks,
Ben

-- 
Ben Greear <greearb@candelatech.com>
Candela Technologies Inc  http://www.candelatech.com

Re: RFC: Add precise timing to wifi association messages?

[Ben Greear]

On 11/13/2013 09:58 AM, Ben Greear wrote:
> Any interest in a patch looking similar to that below for the
> 5 or so messages related to association?  I found it useful for
> tracking down why it was taking longer than expected to roam
> to a new AP...
> 
> 
> diff --git a/net/mac80211/mlme.c b/net/mac80211/mlme.c
> index d2510c0..2e96813 100644
> --- a/net/mac80211/mlme.c
> +++ b/net/mac80211/mlme.c
> @@ -908,6 +908,12 @@ static void ieee80211_send_assoc(struct ieee80211_sub_if_data *sdata)
>                 memcpy(pos, assoc_data->ie + offset, noffset - offset);
>         }
> 
> +       {
> +               struct timeval tv;
> +               do_gettimeofday(&tv);
> +               sdata_info(sdata, "send_assoc, calling prepare_tx at: %lu.%lu\n",
> +                          tv.tv_sec, tv.tv_usec);
> +       }
>         drv_mgd_prepare_tx(local, sdata);
> 
>         IEEE80211_SKB_CB(skb)->flags |= IEEE80211_TX_INTFL_DONT_ENCRYPT;

I chose a poor example here...my intention is to just add timers to existing
messages...

Thanks,
Ben

> 
> 
> Thanks,
> Ben
> 


-- 
Ben Greear <greearb@candelatech.com>
Candela Technologies Inc  http://www.candelatech.com

Re: RFC: Add precise timing to wifi association messages?

[Johannes Berg]

On Wed, 2013-11-13 at 10:01 -0800, Ben Greear wrote:

> I chose a poor example here...my intention is to just add timers to existing
> messages...

What does this do that printk timestamps don't?

johannes

Re: RFC: Add precise timing to wifi association messages?

[Ben Greear]

On 11/13/2013 10:18 AM, Johannes Berg wrote:
> On Wed, 2013-11-13 at 10:01 -0800, Ben Greear wrote:
> 
>> I chose a poor example here...my intention is to just add timers to existing
>> messages...
> 
> What does this do that printk timestamps don't?

Sub-second precision, and the same in 'dmesg' output.

There may be a way to get /var/log/messages to show sub-second
precision, but at least it is not enabled by default on the systems
I use.  dmesg has no timestamps at all from what I can tell.

Things like ath9k debugging typically do not go to /var/log/messages
at all, so I was stuck using dmesg (I'll post a similar patch for ath9k
debugging in case someone likes it.)

The format I chose matches wpa_supplicant logs as well, which I found
useful.

Thanks,
Ben

-- 
Ben Greear <greearb@candelatech.com>
Candela Technologies Inc  http://www.candelatech.com

Re: RFC: Add precise timing to wifi association messages?

[Johannes Berg]

On Wed, 2013-11-13 at 10:24 -0800, Ben Greear wrote:
> On 11/13/2013 10:18 AM, Johannes Berg wrote:
> > On Wed, 2013-11-13 at 10:01 -0800, Ben Greear wrote:
> > 
> >> I chose a poor example here...my intention is to just add timers to existing
> >> messages...
> > 
> > What does this do that printk timestamps don't?
> 
> Sub-second precision, and the same in 'dmesg' output.
> 
> There may be a way to get /var/log/messages to show sub-second
> precision, but at least it is not enabled by default on the systems
> I use.  dmesg has no timestamps at all from what I can tell.

Err. Just set CONFIG_PRINTK_TIME in your kernel.

johannes

Re: RFC: Add precise timing to wifi association messages?

[Ben Greear]

On 11/13/2013 10:32 AM, Johannes Berg wrote:
> On Wed, 2013-11-13 at 10:24 -0800, Ben Greear wrote:
>> On 11/13/2013 10:18 AM, Johannes Berg wrote:
>>> On Wed, 2013-11-13 at 10:01 -0800, Ben Greear wrote:
>>>
>>>> I chose a poor example here...my intention is to just add timers to existing
>>>> messages...
>>>
>>> What does this do that printk timestamps don't?
>>
>> Sub-second precision, and the same in 'dmesg' output.
>>
>> There may be a way to get /var/log/messages to show sub-second
>> precision, but at least it is not enabled by default on the systems
>> I use.  dmesg has no timestamps at all from what I can tell.
> 
> Err. Just set CONFIG_PRINTK_TIME in your kernel.

Ok, I didn't realize that was available.

Thanks,
Ben

> 
> johannes
> 


-- 
Ben Greear <greearb@candelatech.com>
Candela Technologies Inc  http://www.candelatech.com