prism2-usb init on recent kernel versions

[Konstantin Kletschke]

Hi Folks!

We are using the prism2-usb and p80211 modules in our application on an
embedded ARM9 platform for a while now.
The application went into production use with linux 2.6.10. In recent
Kernels, namely 2.6.14 or 2.6.15 i have the fear doubt that the
prism2-usb takes 2 seconds longer to init the WLAN stick (its a
dwl-122g). I am asking here if there is a possibility to get rid of this
second, bootuptime and wlan connect is very critical in our application.

To measure timing of the stuff I take the output of serial console and
pipe it through an expect script which puts timestamps to the kernel
messages. This is our known to be fast old setup:

1.944
4.147 prism2usb_init: prism2_usb.o: 0.2.1-pre23 Loaded
4.150 prism2usb_init: dev_info is: prism2_usb
4.155 usbcore: registered new driver prism2_usb
4.487 ident: nic h/w: id=0x8026 1.0.0
4.501 ident: pri f/w: id=0x15 1.1.3
4.509 ident: sta f/w: id=0x1f 1.7.1
4.522 MFI:SUP:role=0x00:id=0x01:var=0x01:b/t=1/1
4.532 CFI:SUP:role=0x00:id=0x02:var=0x02:b/t=1/1
4.543 PRI:SUP:role=0x00:id=0x03:var=0x01:b/t=1/4
4.552 STA:SUP:role=0x00:id=0x04:var=0x01:b/t=1/12
4.562 PRI-CFI:ACT:role=0x01:id=0x02:var=0x02:b/t=1/1
4.571 STA-CFI:ACT:role=0x01:id=0x02:var=0x02:b/t=1/1
4.582 STA-MFI:ACT:role=0x01:id=0x01:var=0x01:b/t=1/1
4.590 Prism2 card SN: 000000000000

~2.2 seconds with linux-wlan-ng-0.2.3.

Now take a look at linux-2.6.16 with linux-wlan-ng-0.2.4+svn20060414:

2.491
5.612 ident: nic h/w: id=0x8026 1.0.0
5.623 ident: pri f/w: id=0x15 1.1.3
5.632 ident: sta f/w: id=0x1f 1.7.1
5.642 MFI:SUP:role=0x00:id=0x01:var=0x01:b/t=1/1
5.652 CFI:SUP:role=0x00:id=0x02:var=0x02:b/t=1/1
5.662 PRI:SUP:role=0x00:id=0x03:var=0x01:b/t=1/4
5.672 STA:SUP:role=0x00:id=0x04:var=0x01:b/t=1/12
5.682 PRI-CFI:ACT:role=0x01:id=0x02:var=0x02:b/t=1/1
5.692 STA-CFI:ACT:role=0x01:id=0x02:var=0x02:b/t=1/1
5.702 STA-MFI:ACT:role=0x01:id=0x01:var=0x01:b/t=1/1
5.711 Prism2 card SN: 000000000000

over all you see getting the ident stuff lasts 1.2s longer than the
old version.
Additionally I have the Problem init failing sometimes until a timeout
reinits again (I suppose, I am only beginning to investigate the
linux-wlan-ng code yet).
Actually it does not happen every time but more often on 2.6.16 than
2.6.14. I am not able to reproduce it this day (wtf?). It is
hfa384x_usbin_ctlx complaining about CTLX stuff.

Kind Regards, Konsti

[Chris Rankin]

Post by Konstantin Kletschke
To measure timing of the stuff I take the output of serial console and
pipe it through an expect script which puts timestamps to the kernel
1.944
4.147 prism2usb_init: prism2_usb.o: 0.2.1-pre23 Loaded
4.150 prism2usb_init: dev_info is: prism2_usb
4.155 usbcore: registered new driver prism2_usb
4.487 ident: nic h/w: id=0x8026 1.0.0
4.501 ident: pri f/w: id=0x15 1.1.3
4.509 ident: sta f/w: id=0x1f 1.7.1
4.522 MFI:SUP:role=0x00:id=0x01:var=0x01:b/t=1/1
4.532 CFI:SUP:role=0x00:id=0x02:var=0x02:b/t=1/1
4.543 PRI:SUP:role=0x00:id=0x03:var=0x01:b/t=1/4
4.552 STA:SUP:role=0x00:id=0x04:var=0x01:b/t=1/12
4.562 PRI-CFI:ACT:role=0x01:id=0x02:var=0x02:b/t=1/1
4.571 STA-CFI:ACT:role=0x01:id=0x02:var=0x02:b/t=1/1
4.582 STA-MFI:ACT:role=0x01:id=0x01:var=0x01:b/t=1/1
4.590 Prism2 card SN: 000000000000
~2.2 seconds with linux-wlan-ng-0.2.3.
2.491
5.612 ident: nic h/w: id=0x8026 1.0.0
5.623 ident: pri f/w: id=0x15 1.1.3
5.632 ident: sta f/w: id=0x1f 1.7.1
5.642 MFI:SUP:role=0x00:id=0x01:var=0x01:b/t=1/1
5.652 CFI:SUP:role=0x00:id=0x02:var=0x02:b/t=1/1
5.662 PRI:SUP:role=0x00:id=0x03:var=0x01:b/t=1/4
5.672 STA:SUP:role=0x00:id=0x04:var=0x01:b/t=1/12
5.682 PRI-CFI:ACT:role=0x01:id=0x02:var=0x02:b/t=1/1
5.692 STA-CFI:ACT:role=0x01:id=0x02:var=0x02:b/t=1/1
5.702 STA-MFI:ACT:role=0x01:id=0x01:var=0x01:b/t=1/1
5.711 Prism2 card SN: 000000000000
over all you see getting the ident stuff lasts 1.2s longer than the old version.

Are you sure? On your original "fast" set-up, the time between the prism2_usb module loading and
the last line of your log is only (4.59 - 4.147) = 0.443 seconds. Your second log doesn't go back
as far as when the prism2_usb module was loaded, but (5.711 - 5.612) ~ 0.1 second, which is
comparable to (4.59 - 5.612) seconds.

Since the WLAN code cannot possibly be running before its modules are loaded into memory, it looks
to me like your slowdown might be elsewhere.

Cheers,
Chris


Send instant messages to your online friends http://uk.messenger.yahoo.com

[Konstantin Kletschke]

Post by Chris Rankin

Post by Konstantin Kletschke
1.944
4.147 prism2usb_init: prism2_usb.o: 0.2.1-pre23 Loaded
2.491
5.612 ident: nic h/w: id=0x8026 1.0.0

Are you sure? On your original "fast" set-up, the time between the prism2_usb module loading and
the last line of your log is only (4.59 - 4.147) = 0.443 seconds. Your second log doesn't go back
as far as when the prism2_usb module was loaded, but (5.711 - 5.612) ~ 0.1 second, which is
comparable to (4.59 - 5.612) seconds.

I am referreing to the first both lines, the timestamp is added in front
of the line when it gets printed. So first stamp is printed when command
before is executed, second when the first output from linux-wlan-ng
occurs.
No other stuff is executed meanwhile and this seems to take a second
longer on recent kernels, I tried everything.

4.1-1.9=2.2

vs.

5.6-2.4=3.2

Kind regards, Konsti

[Chris Rankin]

Post by Konstantin Kletschke

Post by Konstantin Kletschke
1.944
4.147 prism2usb_init: prism2_usb.o: 0.2.1-pre23 Loaded
2.491
5.612 ident: nic h/w: id=0x8026 1.0.0

I am referreing to the first both lines, the timestamp is added in front
of the line when it gets printed. So first stamp is printed when command
before is executed, second when the first output from linux-wlan-ng
occurs.

Except that the first message logged each time is completely different. The "ident" line is logged
long after the "prism2usb_init" line, so you are comparing apples with oranges here. If the new
prism2_usb module doesn't log a "prism2usb_init" message then add one, and see how the interval
between "module init" and "ident" has changed.

Cheers,
Chris


Send instant messages to your online friends http://uk.messenger.yahoo.com

[Konstantin Kletschke]

Except that the first message logged each time is completely
different. The "ident" line is logged long after the "prism2usb_init"

Well, I see, the quoted text looks different.

line, so you are comparing apples with oranges here. If the new
prism2_usb module doesn't log a "prism2usb_init" message then add one,
and see how the interval between "module init" and "ident" has
changed.

Indeed the time before "ident" is significant different, regardeless
where/when the modules are loaded.
I will create a log providing that tomorrow.

To track down the ting I moved stuff around to get a clue, but the time
to put out "ident" lasts longer on recent kernels.

Konsti