[Hardy] Intel 3945ABG Long boot delays while "Loading hardware drivers"

Bug #192845 reported by Mikael Nilsson on 2008-02-18
38
Affects Status Importance Assigned to Milestone
linux (Ubuntu)
Medium
Unassigned
udev (Ubuntu)
Medium
Unassigned

Bug Description

Binary package hint: udev

Every time I boot, my laptop (a Dell XPS M1710) hangs for about a minute while "Loading hardware drivers...". Nothing is printed, no disk activity, nothing. It then proceeds as normal, and everything works as expected.

There are similar reports in bug #102982, but I blacklisted the intel_rng driver without any improvement. Enabling the radio kill switch during boot *does* take the delay way though.

Saïvann : The bug is opened in udev and linux because we're not sure of which is the right one.

Mikael Nilsson (mini) wrote :
Saivann Carignan (oxmosys) wrote :

Thanks for your bug report and for your contribution to ubuntu. Can you boot your computer without "splash" and "quiet" to get more detailed outputs which cause this slow boot process? You can do this by following these steps :

   1.Press Esc during Grub boot delay to access the boot menu.
   2.Select your actual Ubuntu boot line and press "e" to edit it.
   3.Select the "kernel" line and press "e" to edit it.
   4. At the end of the line, remove "splash" and "quiet" and press "enter".
   5.Type "b" to boot the custom boot line.

Mikael Nilsson (mini) wrote :

Here's the relevant part of dmesg, matching what I saw visually:

[ 35.593666] nvidia: module license 'NVIDIA' taints kernel.
[ 34.037327] iwl3945: Intel(R) PRO/Wireless 3945ABG/BG Network Connection driver for Linux, 1.2.0
[ 34.037403] iwl3945: Copyright(c) 2003-2007 Intel Corporation
[ 34.037600] ACPI: PCI Interrupt 0000:0c:00.0[A] -> GSI 17 (level, low) -> IRQ 17
[ 34.037770] PCI: Setting latency timer of device 0000:0c:00.0 to 64
[ 34.037789] iwl3945: Detected Intel PRO/Wireless 3945ABG Network Connection
[ 34.096182] Bluetooth: Core ver 2.11
[ 34.096303] NET: Registered protocol family 31
[ 34.096356] Bluetooth: HCI device and connection manager initialized
[ 34.096410] Bluetooth: HCI socket layer initialized
[ 34.132660] Bluetooth: HCI USB driver ver 2.9
[ 34.134126] usbcore: registered new interface driver hci_usb
[ 36.196611] ACPI: PCI Interrupt 0000:01:00.0[A] -> GSI 16 (level, low) -> IRQ 16
[ 36.196726] PCI: Setting latency timer of device 0000:01:00.0 to 64
[ 36.196853] NVRM: loading NVIDIA UNIX x86 Kernel Module 169.09 Fri Jan 11 14:38:28 PST 2008
[ 34.451443] iwl3945: Tunable channels: 13 802.11bg, 23 802.11a channels
[ 34.452721] wmaster0: Selected rate control algorithm 'iwl-3945-rs'
[ 34.568494] ACPI: PCI Interrupt 0000:00:1b.0[A] -> GSI 21 (level, low) -> IRQ 21
[ 34.568617] PCI: Setting latency timer of device 0000:00:1b.0 to 64
[ 34.637147] udev: renamed network interface wmaster0 to eth1
[ 65.057928] Adding 4393768k swap on /dev/sda3. Priority:-1 extents:1 across:4393768k
[ 67.293005] EXT3 FS on sda1, internal journal
[ 66.205823] ip_tables: (C) 2000-2006 Netfilter Core Team
[ 66.755568] ACPI: ACPI Dock Station Driver
[ 66.809284] toshiba_acpi: Unknown parameter `hotkeys_over_acpi'
[ 69.101713] NET: Registered protocol family 10
[ 69.101924] lo: Disabled Privacy Extensions
[ 69.102245] ADDRCONF(NETDEV_UP): eth0: link is not ready
[ 69.102967] ADDRCONF(NETDEV_UP): wlan0_rename: link is not ready
[ 69.285876] lp: driver loaded but no devices found
[ 69.353508] ppdev: user-space parallel port driver
[ 69.533836] audit(1203324923.890:2): operation="inode_permission" request_mask="a::" denied_mask="a::" name="/dev/tty" pid=5420 profile="/usr/sbin/cupsd" namespace="default"
[ 69.585376] apm: BIOS not found.
[ 70.676244] Bluetooth: L2CAP ver 2.9
[ 70.676251] Bluetooth: L2CAP socket layer initialized
[ 70.918883] Bluetooth: RFCOMM socket layer initialized
[ 70.918902] Bluetooth: RFCOMM TTY layer initialized
[ 70.918905] Bluetooth: RFCOMM ver 1.8

The delay is after the line
[ 34.637147] udev: renamed network interface wmaster0 to eth1

obviously

No messages are shown in the meantime.

Saivann Carignan (oxmosys) wrote :

Thanks for this detailed informations. Since this bug seems to happen in udev with a specific wireless card, can you also provide the file created by this command on a terminal :

lspci -vvnn > lspci-vvnn.txt

Mikael Nilsson (mini) wrote :
Saivann Carignan (oxmosys) wrote :

It looks like a driver initialization problem for your wifi Network controller [0280]: Intel Corporation PRO/Wireless 3945ABG Network Connection [8086:4222] (rev 02)

There is several bugs that speaks of problem with the same cards but not a long boot time during Loading hardware drivers.. Can you confirm if your wifi card is working properly? Also which ubuntu version do you use, Gutsy? Can you download the latest ubuntu hardy LiveCD from here http://cdimage.ubuntu.com/releases/hardy/alpha-4/ and confirm if you still get that problem with the LiveCD?

Thanks for all the information you provided so far.

Saivann Carignan (oxmosys) wrote :

Note : bug 106256 seems to describe the same issues.

Mikael Nilsson (mini) wrote :

Sorry, I never mentioned - I already run Hardy, updated today.

uname -a: Linux daneel 2.6.24-8-generic #1 SMP Thu Feb 14 20:40:45 UTC 2008 i686 GNU/Linux

$ lsmod |grep 3945
iwl3945 89844 0
iwlwifi_mac80211 220004 1 iwl3945

Wireless works flawlessly. I haven't tried booting with radio kill switch on though.

Saivann Carignan (oxmosys) wrote :

Mikael Nilsson : In order to give complete informations to the ubuntu kernel-team, can you also provide the files created by these commands :

1. uname -a > uname-a.log
2. cat /proc/version_signature > version.log

According to the fact that this bug can be reproduced on a fresh hardy install, I set the package to linux-source-2.6.24 and I assign the bug to the ubuntu-kernel-team. Thanks a lot for all the time you took to improve that bug report and to help improving ubuntu.

Changed in udev:
assignee: nobody → ubuntu-kernel-team
importance: Undecided → Medium
status: New → Confirmed
Mikael Nilsson (mini) wrote :

The delay does not happen with the radio kill switch ON (= WiFi off).

Mikael Nilsson (mini) wrote :
C de-Avillez (hggdh2) wrote :

This does not seem to be restricted to the Intel wireless card. I have a BCM4318, and I also get it:

Feb 22 11:08:40 xango2 kernel: [ 294.260774] ACPI: PCI Interrupt 0000:00:14.2[A] -> GSI 16 (level, low) -> IRQ 16
Feb 22 11:08:40 xango2 kernel: [ 294.261429] phy0: Selected rate control algorithm 'simple'
Feb 22 11:08:40 xango2 kernel: [ 294.308539] input,hidraw1: USB HID v1.11 Mouse [Broadcom Corp] on usb-0000:00:13.3-2.3
Feb 22 11:08:40 xango2 kernel: [ 294.308631] usbcore: registered new interface driver usbhid
Feb 22 11:08:40 xango2 kernel: [ 294.308636] /build/buildd/linux-2.6.24/drivers/hid/usbhid/hid-core.c: v2.6:USB HID core driver
Feb 22 11:08:40 xango2 kernel: [ 296.305805] udev: renamed network interface wmaster0 to eth1
Feb 22 11:08:40 xango2 kernel: [ 328.351214] Adding 5277344k swap on /dev/sda3. Priority:-1 extents:1 across:5277344k
Feb 22 11:08:40 xango2 kernel: [ 328.704532] EXT3 FS on dm-0, internal journal

Additional data:

hggdh@xango2:/tmp $ cat /proc/version
Linux version 2.6.24-8-generic (buildd@yellow) (gcc version 4.2.3 (Ubuntu 4.2.3-1ubuntu2)) #1 SMP Thu Feb 14 20:13:27 UTC 2008
hggdh@xango2:/tmp $ uname -a
Linux xango2 2.6.24-8-generic #1 SMP Thu Feb 14 20:13:27 UTC 2008 x86_64 GNU/Linux
hggdh@xango2:/tmp $ cat /proc/version
Linux version 2.6.24-8-generic (buildd@yellow) (gcc version 4.2.3 (Ubuntu 4.2.3-1ubuntu2)) #1 SMP Thu Feb 14 20:13:27 UTC 2008
hggdh@xango2:/tmp $ cat /proc/version_signature
Ubuntu 2.6.24-8.14-generic
hggdh@xango2:/tmp $

I will attach a 'lspci -vnnn'. I also had udev running in debug mode; if you want it, tell me, and I will upload the syslog piece and the udev actions themselves.

C de-Avillez (hggdh2) wrote :
C de-Avillez (hggdh2) wrote :
C de-Avillez (hggdh2) wrote :

Another interesting match between the original reporter's dmesg and mine is that the wireless comes up as wmaster0, is renamed to eth1 (per the udev rules), and *then* again renamed to wlan0_rename.

This one really sounds like udev.

For the record, my laptop is a Dell Inspiron 1721.

Saivann Carignan (oxmosys) wrote :

hggdh : According to your comment about the wmaster0 renamed into eth1, I set the status of the bug to Triaged to help it getting more attention since I suspect that we have enough information for developers, I also open again the bug in udev in case that it is really a udev bug.

Changed in linux:
status: Confirmed → Triaged
Changed in udev:
importance: Undecided → Medium
status: New → Triaged
description: updated
Mikael Nilsson (mini) wrote :

hggdh: Indeed, the dmesg shows the delay happening at very much the same time as me. Can you boot with wireless off and see of the delay disappears?

description: updated
Mikael Nilsson (mini) wrote :

Here's a bootchart for (possibly) this issue:

http://ubuntuforums.org/showthread.php?p=4381896#post4381896

C de-Avillez (hggdh2) wrote :

Tried with the wireless disabled on boot -- no visible difference on the wait:

[ 24.813814] input,hidraw0: USB HID v1.00 Device [C-Media USB Headphone Set ] on usb-0000:00:13.5-4.2
[ 24.816537] input: Logitech USB-PS/2 Optical Mouse as /devices/pci0000:00/0000:00:13.5/usb1/1-4/1-4.3/1-4.3.3/1-4.3.3:1.0/input
/input11
[ 24.877817] input,hidraw1: USB HID v1.10 Mouse [Logitech USB-PS/2 Optical Mouse] on usb-0000:00:13.5-4.3.3
[ 24.878007] usbcore: registered new interface driver usbhid
[ 24.878046] /build/buildd/linux-2.6.24/drivers/hid/usbhid/hid-core.c: v2.6:USB HID core driver
[ 24.878148] usbcore: registered new interface driver snd-usb-audio
[ 25.018810] udev: renamed network interface eth1 to eth2
[ 25.062423] udev: renamed network interface wmaster0_rename to eth1
[ 59.451230] Adding 5277344k swap on /dev/sda3. Priority:-1 extents:1 across:5277344k
[ 59.813466] EXT3 FS on dm-0, internal journal
[ 62.211831] kjournald starting. Commit interval 5 seconds
[ 62.212076] EXT3 FS on sda2, internal journal
[ 62.212080] EXT3-fs: mounted filesystem with ordered data mode.
[ 62.235145] kjournald starting. Commit interval 5 seconds

What was interesting is udev now correctly renaming the network interfaces.

C de-Avillez (hggdh2) wrote :

On the failure to rename the wireless interface: I ran a 'ifconfig -a', and eth1 has a weird HWaddr: 00-19-7E-B0-17-C4-00-00-00-00-00-00-00-00-00-00. Even more, udev is *not* renaming the wireless correctly, as I stated in my previous comment.

eth0 Link encap:Ethernet HWaddr 00:19:b9:81:c6:1d
          inet addr:192.168.248.246 Bcast:255.255.255.255 Mask:255.255.252.0
          inet6 addr: fe80::219:b9ff:fe81:c61d/64 Scope:Link
          UP BROADCAST RUNNING MULTICAST MTU:1500 Metric:1
          RX packets:208272 errors:0 dropped:0 overruns:0 frame:0
          TX packets:159465 errors:0 dropped:0 overruns:0 carrier:0
          collisions:0 txqueuelen:1000
          RX bytes:291363103 (277.8 MB) TX bytes:12777095 (12.1 MB)
          Interrupt:21

eth1 Link encap:UNSPEC HWaddr 00-19-7E-B0-17-C4-00-00-00-00-00-00-00-00-00-00
          BROADCAST MULTICAST MTU:1500 Metric:1
          RX packets:0 errors:0 dropped:0 overruns:0 frame:0
          TX packets:0 errors:0 dropped:0 overruns:0 carrier:0
          collisions:0 txqueuelen:1000
          RX bytes:0 (0.0 B) TX bytes:0 (0.0 B)

lo Link encap:Local Loopback
          inet addr:127.0.0.1 Mask:255.0.0.0
          inet6 addr: ::1/128 Scope:Host
          UP LOOPBACK RUNNING MTU:16436 Metric:1
          RX packets:1156 errors:0 dropped:0 overruns:0 frame:0
          TX packets:1156 errors:0 dropped:0 overruns:0 carrier:0
          collisions:0 txqueuelen:0
          RX bytes:674126 (658.3 KB) TX bytes:674126 (658.3 KB)

vmnet1 Link encap:Ethernet HWaddr 00:50:56:c0:00:01
          inet addr:192.168.100.1 Bcast:192.168.100.255 Mask:255.255.255.0
          inet6 addr: fe80::250:56ff:fec0:1/64 Scope:Link
          UP BROADCAST RUNNING MULTICAST MTU:1500 Metric:1
          RX packets:0 errors:0 dropped:0 overruns:0 frame:0
          TX packets:117 errors:0 dropped:0 overruns:0 carrier:0
          collisions:0 txqueuelen:1000
          RX bytes:0 (0.0 B) TX bytes:0 (0.0 B)

vmnet8 Link encap:Ethernet HWaddr 00:50:56:c0:00:08
          inet addr:192.168.50.1 Bcast:192.168.50.255 Mask:255.255.255.0
          inet6 addr: fe80::250:56ff:fec0:8/64 Scope:Link
          UP BROADCAST RUNNING MULTICAST MTU:1500 Metric:1
          RX packets:0 errors:0 dropped:0 overruns:0 frame:0
          TX packets:117 errors:0 dropped:0 overruns:0 carrier:0
          collisions:0 txqueuelen:1000
          RX bytes:0 (0.0 B) TX bytes:0 (0.0 B)

wlan0_rename Link encap:Ethernet HWaddr 00:19:7e:b0:17:c4
          BROADCAST MULTICAST MTU:1500 Metric:1
          RX packets:0 errors:0 dropped:0 overruns:0 frame:0
          TX packets:0 errors:0 dropped:0 overruns:0 carrier:0
          collisions:0 txqueuelen:1000
          RX bytes:0 (0.0 B) TX bytes:0 (0.0 B)

Federico Foschini (undicizeri) wrote :

same bug here. I'm using hardy heron on a toshiba A100-730 laptop with inter 3945 card. If i turn off the wireless switch boot speeds up by 30 seconds.

Same issue as others. I have the Intel Pro Wireless 3945 also using the iwl3945 driver under the current Hardy. I'm using a Gateway C-140XL laptop. I figure there's not point in posting what everyone else has; I just want to confirm on another laptop.

C de-Avillez (hggdh2) wrote :

70-persistent-net.rules follows

# This file maintains persistent names for network interfaces.
# See udev(7) for syntax.
#
# Entries are automatically added by the 75-persistent-net-generator.rules
# file; however you are also free to add your own entries.

# PCI device 0x14e4:0x170c (b44)
SUBSYSTEM=="net", DRIVERS=="?*", ATTRS{address}=="00:19:b9:81:c6:1d", NAME="eth0"

# PCI device 0x14e4:0x4312 (bcm43xx)
SUBSYSTEM=="net", DRIVERS=="?*", ATTRS{address}=="00:19:7e:b0:17:c4", NAME="eth1"

# USB device 0x0b95:0x7720 (asix)
SUBSYSTEM=="net", DRIVERS=="?*", ATTRS{address}=="00:50:b6:41:d2:73", NAME="eth2"

# USB device 0x03f0:0x1c1d (rndis_host)
SUBSYSTEM=="net", DRIVERS=="?*", ATTRS{address}=="80:00:60:0f:e8:00", NAME="eth3"

# USB device 0x0b95:0x7720 (asix)
SUBSYSTEM=="net", ACTION=="add", DRIVERS=="?*", ATTR{address}=="10:c2:3e:80:ff:ff", ATTR{type}=="1", NAME="eth4"

# USB device 0x0b95:0x7720 (asix)
SUBSYSTEM=="net", ACTION=="add", DRIVERS=="?*", ATTR{address}=="40:eb:3e:80:ff:ff", ATTR{type}=="1", NAME="eth5"

# USB device 0x0b95:0x7720 (asix)
SUBSYSTEM=="net", ACTION=="add", DRIVERS=="?*", ATTR{address}=="a0:ec:3e:80:ff:ff", ATTR{type}=="1", NAME="eth6"

Not a linux bug, very definitely udev

Changed in linux:
status: Triaged → Invalid
Mackenzie Morgan (maco.m) wrote :

I have this wireless card with the iwl3945 driver on Hardy, and I don't have this issue. All of my boots, with the exception of the one where fsck ran, have been under 30 seconds. The network card portion of my bootchart lasts less than 3 seconds. Perhaps there is an additional factor coming into play that means only some of these cards are affected?

Ernst Oudhof (e-oudhof) wrote :

This seems related to the device renaming, this doesn't work correctly if old persistent rules are present for the wireless card. Removing these lines from /etc/udev/rules.d/70-persistent-net.rules solves the problem for me. (also the device is now named wlan0 instead of wlan0_rename). A new correct entry will be added by 75-persistent-net-generator.rules.

Thanks Ernst!

That fix brought my boot-up time from 67 seconds to about 33 seconds. It was driving me nuts, but now bootup is much more acceptable.

My /etc/udev/rules.d/70-persistent-net.rules does not contain any old entries, and
my boot-times are still too long. Turning off Wifi before boot reduces boot-times with
about 30 seconds.

Using iwl3945 driver on Ubuntu Hardy Heron alpha 6 on an IBM T60.

Heres my /etc/udev/rules.d/70-persistent-net.rules:
-----------------
# This file maintains persistent names for network interfaces.
# See udev(7) for syntax.
#
# Entries are automatically added by the 75-persistent-net-generator.rules
# file; however you are also free to add your own entries.

# PCI device 0x8086:0x109a (e1000)
SUBSYSTEM=="net", DRIVERS=="?*", ATTRS{address}=="00:16:41:ae:16:a1", NAME="eth1"

# PCI device 0x8086:0x4227 (iwl3945)
SUBSYSTEM=="net", DRIVERS=="?*", ATTRS{address}=="00:19:d2:07:14:a2", NAME="eth0"
------------------

Attached are my bootcharts with and without wifi.

and on...

Ernst Oudhof (e-oudhof) wrote :

I think I nailed it....

udev tries to rename the wmaster* device generated by mac80211. It should only rename the real interface named wlan*.
By adding the following to /etc/udev/rules.d/05-options.rules the wmaster* devices will be ignored and renaming works correctly again... ( so no boot delay :-) )

#Do nothing with wmaster virtual devices
SUBSYSTEM=="net", KERNEL=="wmaster*", OPTIONS+="ignore_device"

Also attached as patch....

Ernst Oudhof (e-oudhof) wrote :

The patch from my previous post is only needed for rules generated by "old" (e.g. 7.10) 75-persistent-net.rules.
The latest from hardy generates rules which contain ATTR{type}=="1" which won't match the wmaster device.
 But for people who upgrade from 7.10 it might be a nice to have a cleaner upgrade....

Nick B. (futurepilot) wrote :

Adding those lines to /etc/udev/rules.d/05-options.rules worked for me to get rid of the delay. This was a system upgraded from Gutsy.

The patch doesn't actually fix the problem ...
though it's a rather elegant hack

The patch can't be applied though, this would prevent wmaster devices showing up in HAL, etc. and that would be bad.

The right fix is to add ATTR{type}=="1" to the existing autogenerated rules
(the new rules will already have that added)

Filippo Argiolas (fargiolas) wrote :

I've experienced the same problem after upgrading from gusty to hardy a couple of days ago.
I've removed 70-persistent-net.rules to force udev to regenerate it and the boot delay disappeared.
Maybe old rules cleanup should be automated at upgrade time?

István Blahota (blahota) wrote :

I have the same problem with the similar symptoms.
On Gutsy it worked perfectly. It was upgraded to Hardy beta.
30 sec delay on boot, it works only slowly and unstable, and no blue led light at all.

István Blahota (blahota) wrote :

I made what Ernst offered (thanks!). It works (30 sec delay has vanished), but the speed of the connection has remained slow :-(

Then I made a try: I booted the computer with the old Gutsy kernel (instead of the new Hardy beta kernel) and voila!
Wireless speed is excellent again, and everything works :-) Funny workaround.

Saivann Carignan (oxmosys) wrote :

Istvan Blahota : You say that "it works only slowly and unstable", do you mean that your computer is unstable when you use it or just the wireless connexion? If your computer is unstable, I also have problems only when running on battery that I described in bug 189814, in case you want to look if you have the same symptoms.

István Blahota (blahota) wrote :

To Saïvann Carignan:
Just the connection is slow and unstable, the other part of the system is OK.

Josh (jharris0221) wrote :

I, too am having this issue and wanted to add my data.

I'm running a Thinkpad T60p with an Intel Core 2 T5600. The wireless card is a "Intel 802.11abg Mini PCI Express wireless adapter" but I don't know how to find the exact model.

I have a ~28 second delay with the wireless hardware switch on, and that delay is gone with the switch off. I have included the output of bootchart with both the switch off. You can see the process "udev" is hanging.

Also, when I start up I also get "udev: renamed network interface wmaster0 to eth1" and then once I am booted ifconfig shows the name as "wlan0_rename".

Finally, when I shutdown, instead of seeing the graphical splash screen, I see text. It pauses for about 30 seconds, then displays "NetworkManager: <WARN> nm_signal_handler(): Caught signal 15, shutting down normally.
NetworkManager: <info> Caught Termination signal
NetworkManager: <debug> [1206913931.769927] nm_print_open_socks(): Open Sockets List:"
and it ends there. Is this related or a separate issue? Seems too similar (a 30 sec pause, network related) to not mention.

Josh (jharris0221) wrote :

Little extra info to my previous post: the wireless card is shows up in Ubuntu as "Intel Corporation PRO/Wireless 3945ABG Network Connection"

Filippo Argiolas (fargiolas) wrote :

Josh, Istvan, did you tried to remove 70-persistent-net.rules as I suggested?
If you keep the old one from gutsy it will not work! It has to be regenerated with the new hardy rules from 75-persistent-net-generator.rules.
I've just removed that file and now I have no slowdown.
Regarding stability I didn't notice anything strange.

steffmeister (steffed) wrote :

hey folks, i just wanted to let you know that removing that 70-persistent-net.rules also saved me about 10 seconds, i have a b43 wireless, though.

Per a decision made by the Ubuntu Kernel Team, bugs will longer be assigned to the ubuntu-kernel-team in Launchpad as part of the bug triage process. The ubuntu-kernel-team is being unassigned from this bug report. Refer to https://wiki.ubuntu.com/KernelTeamBugPolicies for more information. Thanks.

To post a comment you must log in.
This report contains Public information  Edit
Everyone can see this information.

Other bug subscribers