HAL

hal takes about 60 seconds to start up

Bug #92647 reported by Jonathan Riddell on 2007-03-15
20
Affects Status Importance Assigned to Milestone
HAL
Fix Released
Medium
hal (Ubuntu)
Medium
Unassigned

Bug Description

Binary package hint: hal

Hal takes a long time to start, around 60 seconds. This is on my laptop. On my desktop it doesn't take a noticable time.

lspci
00:00.0 Host bridge: ATI Technologies Inc RS200/RS200M AGP Bridge [IGP 340M] (rev 02)
00:01.0 PCI bridge: ATI Technologies Inc PCI Bridge [IGP 340M]
00:02.0 USB Controller: ALi Corporation USB 1.1 Controller (rev 03)
00:03.0 Modem: ALi Corporation M5457 AC'97 Modem Controller
00:04.0 Multimedia audio controller: ALi Corporation M5451 PCI AC-Link Controller Audio Device (rev 02)
00:06.0 Bridge: ALi Corporation M7101 Power Management Controller [PMU]
00:07.0 ISA bridge: ALi Corporation M1533/M1535 PCI to ISA Bridge [Aladdin IV/V/V+]
00:0b.0 Ethernet controller: Broadcom Corporation NetXtreme BCM5901 100Base-TX (rev 01)
00:0c.0 CardBus bridge: Texas Instruments PCI1510 PC card Cardbus Controller
00:0f.0 IDE interface: ALi Corporation M5229 IDE (rev c4)
01:05.0 VGA compatible controller: ATI Technologies Inc Radeon IGP 330M/340M/350M

C de-Avillez (hggdh2) wrote :

Similar here on a laptop with AMD64, but it is most visible on shutdown, when I lose usplash when shutting down dbus & friends. Takes about a minute to shutdown dbus.

On startup... I will check next boot.

C de-Avillez (hggdh2) wrote :

startup hal takes more than 30 seconds. On shutdown, for my surprise, it was seamless, with absolutely no waits. This is today, yesterday it was not behaving like this.

Martin Pitt (pitti) wrote :

Can you please get a hal debug output, as described on the second half of https://wiki.ubuntu.com/DebuggingRemovableDevices, watch the log output, and see where it hangs for so long? Since it usually starts in some-three seconds, I guess it just hangs in a single operation instead of being generally slow.

Thanks!

Changed in hal:
status: Unconfirmed → Needs Info
C de-Avillez (hggdh2) wrote :

Restarted hald in verbose mode. first timestamp is 09:31:43.595, last timestamp is 09:32:32.162, so about 50 seconds.

There is a forced 1000 ms wait at blockdev (see timestamps 09:32:10.650 onward) for each device found; this piece of init takes about 20 seconds to complete.

Have not yet looked fully into it. I intend to change hald init to verbose & try again.

In above bug, hal takes about a minute to start up. A large chunk seems to come from a long series like this:

09:32:11.652 [I] blockdev.c:686: Looking in /sys/block/dm-0/slaves
09:32:11.653 [I] blockdev.c:698: /sys/block/dm-0/slaves/hda2 -> /sys/block/hda/hda2
09:32:11.653 [I] blockdev.c:698: /sys/block/dm-0/slaves/hda7 -> /sys/block/hda/hda7
09:32:11.653 [I] blockdev.c:734: Done looking in /sys/block/dm-0/slaves
09:32:11.653 [I] blockdev.c:740: Ignoring hotplug event - no parent
09:32:11.653 [W] blockdev.c:1152: Not adding device object
09:32:11.654 [I] blockdev.c:638: block_add: sysfs_path=/sys/block/dm-1 dev=/dev/mapper/system-server is_part=0, parent=0x00000000
09:32:11.655 [I] blockdev.c:681: Waiting 1000ms to wait for device mapper to be ready
09:32:12.656 [I] blockdev.c:686: Looking in /sys/block/dm-1/slaves
[...]

This does not seem to happen on the majority of computers.

Created an attachment (id=9249)
verbose hal log

hal debug output

Martin Pitt (pitti) on 2007-03-21
Changed in hal:
importance: Undecided → Medium
status: Needs Info → Confirmed
Changed in hal:
status: Unknown → Confirmed

Which HAL version is this? I could not find the message (Waiting 1000ms to wait for device mapper to be ready) in current HAL git master code.

This is the latest stable release, 0.5.8.1. This comes from hald/linux/blockdev.c, hotplug_event_begin_add_blockdev():

                /* sleep one second since device mapper needs additional
                 * time before the device file is ready
                 *
                 * this is a hack and will only affect device mapper block
                 * devices. It can go away once the kernel emits a "changed"
                 * event for the device file (this is about to go upstream)
                 * and we can depend on a released kernel with this feature.
                 */
                if (strncmp (hal_util_get_last_element (sysfs_path), "dm-", 3) == 0) {
                        HAL_INFO (("Waiting 1000ms to wait for device mapper to be ready", path));
                        usleep (1000 * 1000);
                }

Indeed git head looks completely different, so let's assume for now that this is fixed already. Thank you!

Changed in hal:
status: Confirmed → Needs Info
Changed in hal:
status: Needs Info → Fix Released
Chris Samuel (chris-csamuel) wrote :

I see the same thing here with Feisty Kubuntu (up to date), each of my LVM's results in a 1 second wait:

"Waiting 1000ms to wait for device mapper to be ready"

So my boot time here has almost doubled from just over 1m to 1m 52s (+/- 3s) - a bit disappointing really as I upgrade thinking I'd see a faster boot! :-(

I've attached the resulting hal.log from here and will attach the bootcharts for my last Edgy boot and latest Feisty boot for comparison.

Chris Samuel (chris-csamuel) wrote :

Bootchart from Kubuntu Edgy immediately prior to upgrade to Feisty showing a boot time of 1m 4s.

Chris Samuel (chris-csamuel) wrote :

Bootchart from Kubuntu Feisty with current updates showing a boot time of 1m 57s, over 50 seconds longer than Edgy.

ACPI?

I noticed starting gkrellm today that it took an oddly long time to startup so I straced it, it was hanging on batt and ac acpi for a long time.

Then I started hal with --verbose=yes --use-syslog and restarted dbus, hal also hung for a long time on those same acpi parts.

Download full text (4.8 KiB)

Startup w/o acpi modules for batt and ac:
root@jkd:~# time /etc/init.d/dbus start
 * Starting system message bus dbus [ OK ]
 * Starting Hardware abstraction layer hald [ OK ]
 * Starting DHCP D-Bus daemon dhcdbd [ OK ]
 * Starting network connection manager NetworkManager [ OK ]
 * Starting Avahi mDNS/DNS-SD Daemon: avahi-daemon [ OK ]
 * Starting network events dispatcher NetworkManagerDispatcher [ OK ]

real 0m6.661s
user 0m0.169s
sys 0m0.097s

root@jkd:~# modprobe ac
root@jkd:~# modprobe battery
root@jkd:~# time /etc/init.d/dbus start
 * Starting system message bus dbus [ OK ]
 * Starting Hardware abstraction layer hald [ OK ]
 * Starting DHCP D-Bus daemon dhcdbd [ OK ]
 * Starting network connection manager NetworkManager [ OK ]
 * Starting Avahi mDNS/DNS-SD Daemon: avahi-daemon [ OK ]
 * Starting network events dispatcher NetworkManagerDispatcher [ OK ]

real 1m10.391s
user 0m0.261s
sys 0m0.149s

And this is what syslog says:
Mar 31 01:17:06 jkd hald[8852]: 01:17:06.499 [I] acpi.c:1225: acpi_add: acpi_path=/proc/acpi/battery/BAT0 acpi_type=0, parent=0x00000000
Mar 31 01:17:44 jkd hald[8852]: 01:17:44.505 [D] acpi.c:162: Current voltage is unknown, smaller than 501001765435r greater than design
Mar 31 01:17:44 jkd hald[8852]: 01:17:44.519 [I] acpi.c:1197: Add callouts completed udi=/org/freedesktop/Hal/devices/acpi_BAT0
Mar 31 01:17:44 jkd hald[8852]: 01:17:44.520 [I] hald.c:106: Added device to GDL; udi=/org/freedesktop/Hal/devices/acpi_BAT0
Mar 31 01:17:44 jkd hald[8852]: 01:17:44.520 [I] acpi.c:1225: acpi_add: acpi_path=/proc/acpi/processor/CPU0 acpi_type=1, parent=0x00000000
Mar 31 01:17:44 jkd hald[8852]: 01:17:44.534 [I] acpi.c:1197: Add callouts completed udi=/org/freedesktop/Hal/devices/acpi_CPU0
Mar 31 01:17:44 jkd hald[8852]: 01:17:44.534 [I] hald.c:106: Added device to GDL; udi=/org/freedesktop/Hal/devices/acpi_CPU0
Mar 31 01:17:44 jkd hald[8852]: 01:17:44.534 [I] acpi.c:1225: acpi_add: acpi_path=/proc/acpi/ac_adapter/AC acpi_type=3, parent=0x00000000
Mar 31 01:18:05 jkd hald[8852]: 01:18:05.011 [D] acpi.c:162: Current voltage is unknown, smaller than 501001765435r greater than design
Mar 31 01:18:05 jkd hald[8852]: 01:18:05.055 [I] acpi.c:1197: Add callouts completed udi=/org/freedesktop/Hal/devices/acpi_AC
Mar 31 01:18:05 jkd hald[8852]: 01:18:05.055 [I] hald.c:106: Added device to GDL; udi=/org/freedesktop/Hal/devices/acpi_AC
Mar 31 01:18:05 jkd hald[8852]: 01:18:05.056 [I...

Read more...

David Meier (droebbel-melta) wrote :

Same Problem here, waiting 1 sec for each device manager (evms) device.

This seems to be a kernel problem, it takes a long time just to modprobe battery and thermal as well.

Chris Samuel (chris-csamuel) wrote :

I think Jason is looking at a different problem, the slowdown I see is purely down to HAL as I'm running on a desktop with no battery or thermal ACPI modules loaded and the HAL message is quite explicit that it is HAL itself waiting for 1 second per logical volume and the upstream bug report shows the code in HAL that causes this problem.

See https://bugs.freedesktop.org/show_bug.cgi?id=10364#c3

I now see this on every box that is running Feisty that has a number of logical volumes.. :-(

Any ideas when the upstream fix will be available in Feisty ?

yes, I've found that my problem is actually the kernel, 2.6.20 doesn't play well with ACPI on quite a few systems, it shows it's head when I modprobe battery,ac and thermal with longer than usual pauses, and then really shows up with applications like kpowermanager, gkrellm, and hal.

Martin Pitt (pitti) wrote :

Jason, can you please file a separate bug against linux-source-2.6.20, please, since it is a completely different problem?

Apparently fixed upstream, so this will get fixed in gutsy when we'll move to hal 0.5.9.

Changed in hal:
status: Confirmed → In Progress
Chris Samuel (chris-csamuel) wrote :

Is a fix going to get backported to Feisty or do we just have to put up with much slower boot times ?

Hi Chris,

Chris Samuel [2007-04-17 11:44 -0000]:
> Is a fix going to get backported to Feisty or do we just have to put up
> with much slower boot times ?

I am afraid not, hal 0.5.9 has major architectural changes which are
inappropriate for feisty-updates. *However*, if we find some people
who test it, we can put it into feisty-backports. Right now I do not
see a principal reason why 0.5.9 should not work at all on Feisty.

C de-Avillez (hggdh2) wrote :

@Martin: if it helps any, I can test it.

Martin Pitt (pitti) wrote :

For anyone who is interested to test hot new crack, I prepared hal 0.5.9 packages which work on current Feisty for me:

  http://people.ubuntu.com/~pitti/packages/hal-gutsy/

They will be uploaded to gutsy as soon as it opens. NB that you need hal-info_20070402-1_all.deb for the new hal package.

Feedback appreciated!

Chris Samuel (chris-csamuel) wrote :

Hi Martin, thanks for the response!

I guess what I'm puzzled about is that looking at what has changed in that part of the code of hald/linux/blockdev.c it appears that they have removed the check to see if it matches the dm- pattern and consequent debug message and usleep(). The comment before the test that triggers the usleep(1000*1000) in the 0.5.8.1 version says:

                /* sleep one second since device mapper needs additional
                 * time before the device file is ready
                 *
                 * this is a hack and will only affect device mapper block
                 * devices. It can go away once the kernel emits a "changed"
                 * event for the device file (this is about to go upstream)
                 * and we can depend on a released kernel with this feature.
                 */

If the current Feisty kernel does emit that "changed" event then would it be safe to just make that usleep() go away ?

Yours,
Confused of Melbourne. :-)

C de-Avillez (hggdh2) wrote :

I downloaded, created the packages, and installed on my Feisty. No problems, and boot time indeed got better. The enforced delay is gone. No side effects, at least not visible.

Matti Lindell (mlind) wrote :

I'd be very interested to see Gutsy's hal appear in feisty-backports. I rebuilt current hal and hal-info from gutsy's archive for feisty, and there's no delay on bootup anymore.
I haven't spotted any regressions so far, but I'm not using any exotic gadgets either. I'll post back the results after few days. Thanks pitti for your efforts on this subject!

I downloaded the debs for libhal, libhalstorage1, hal, and hal-info packages for Gutsy directly from launchpad and installed (via dpkg). I am also happy to report no noticeable side effects (or other weirdness). I can also confirm a reduction in boot speed (5 seconds on my box) and the desire to see Gutsy's hal in feisty-backports. Kudos to M. Pitt and upstream.

C de-Avillez (hggdh2) wrote :

Updated from source package (as provided by Martin above) to Gutsy version. So far no regressions.

Matti Lindell (mlind) wrote :

Thank you for recent feisty-backports upload. I've had zero problems with new hal.
This is probably "Fix Released" now.

Chris Samuel (chris-csamuel) wrote :

Having just stumbled across the backports repositories ( https://help.ubuntu.com/community/UbuntuBackports ) through the latest Kubuntu koffice updates I can now confirm that the hal update in their fixes my problems too!

Excellent work folks, my boot time is down over 20 seconds from 1:15 yesterday to 0:54 today.

Martin Pitt (pitti) wrote :

Excellent, thanks for testing the backports.

Changed in hal:
status: In Progress → Fix Released
Changed in hal:
importance: Unknown → Medium
Changed in hal:
importance: Medium → Unknown
Changed in hal:
importance: Unknown → Medium
To post a comment you must log in.
This report contains Public information  Edit
Everyone can see this information.

Duplicates of this bug

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.