hal takes about 60 seconds to start up

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.

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.

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!

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.

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.

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

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.

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...

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.

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.

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.

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.

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

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!

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. :-)

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.

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.

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

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

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.

Excellent, thanks for testing the backports.