CasperSpeedup

Casper

Background

Casper and the boot process of live-cd images on ARM based hardware is currently very slow. As part of the blueprint mobile-lucid-une-casper-speedup the process needed to be first investigated, profiled and conclusions drawn on that information.

Time-stamping information was added to the call_scripts function in /usr/share/initramfs-tools/scripts/functions of a karmic live-cd, the date binary added, and the initramfs recreated using ARM/ModifyCasper.

The same time-stamping was done with lucid alpha 1 with the same results.

To see the conclusion of the investigations, click here.

Initial Findings

The output from the initial time-stamping.

5 seconds plus (aka, the culprits)

10adduser

26 seconds

19keyboard

23 seconds

24preseed

11 seconds

14locales

8 seconds

45disable_guest_account

8 seconds

Two to 5 seconds (aka, should be looked at)

22sslcert

5 seconds

35fix_language_selection

4 seconds

One second or less (aka, no use optimizing)

10driver_updates

20iso_scan

30custom_installation

01integrity_check

05mountpoints

05mountpoints_lupin

10custom_installation

10ntfs_3g

12fstab

13swap

15autologin

18hostname

20xconfig

22gnome_panel_data

22screensaver

22serialtty

23etc_modules

23networking

25configure_init

30accessibility

31disable_update_notifier

32disable_hibernation

33enable_apport_crashes

34disable_kde_services

36disable_trackerd

37kubuntu_netbook_installer_link

40install_driver_updates

41apt_cdrom

42disable_apparmor

43disable_updateinitramfs

44pk_allow_ubuntu

46disable_services

47unr_ubiquity

More detailed analysis

10adduser

chroot /root debconf-communicate -fnoninteractive casper > /dev/null <<EOF
set passwd/root-password-crypted *
set passwd/user-password-crypted U6aMy0wojraho
set passwd/user-fullname $USERFULLNAME 
set passwd/username $USERNAME
set passwd/user-uid 999
EOF

Takes around 7 seconds.

chroot /root /usr/lib/user-setup/user-setup-apply > /dev/null

Takes around 12 seconds.

chroot /root debconf-communicate -fnoninteractive casper > /dev/null <<EOF
set passwd/root-password-crypted
set passwd/user-password-crypted
set passwd/user-fullname
set passwd/username
set passwd/user-uid
EOF

Takes around 4 seconds.

19keyboard

Each of the

casper-preseed /root console-setup/layoutcode '' false
casper-preseed /root console-setup/variantcode '' false
casper-preseed /root console-setup/modelcode '' false
casper-preseed /root console-setup/optionscode '' false
casper-preseed /root console-setup/codesetcode '' false

Take around 4 seconds each.

24preseed

reply="$(echo "GET preseed/early_command" | chroot /root debconf-communicate -fnoninteractive casper)"
if [ "${reply#0 }" != "$reply" ]; then
        reply="${reply#0 }"
        sh -c "$reply"
fi

Takes around 5 seconds.

14locales

chroot /root /usr/sbin/locale-gen "${LANG}"

Takes around 7 seconds (chroot + generating the locale)

45disable_guest_account

chroot /root dpkg -P gdm-guest-session || true

Takes around 7 seconds to read the database (129858 files and directories according to the output)

22sslcert

chroot /root /usr/sbin/make-ssl-cert generate-default-snakeoil --force-overwrite

3 seconds are spent on the chroot, 1.5 seconds on the "make-ssl-cert:again".

35fix_language_selection

chroot /root fontconfig-voodoo --auto --quiet || true

Pretty much all the 4 seconds are spent here.

The original output

[04:59:48] Calling hook 10driver_updates
[04:59:48] Calling hook 20iso_scan
[04:59:48] Calling hook 30custom_installation
[04:59:50] Calling hook 01integrity_check
[04:59:50] Calling hook 05mountpoints
[04:59:50] Calling hook 05mountpoints_lupin
[04:59:50] Calling hook 10adduser
Shadow passwords are now on.
[05:00:16] Calling hook 10custom_installation
[05:00:16] Calling hook 10ntfs_3g
[05:00:16] Calling hook 12fstab
[05:00:16] Calling hook 13swap
[05:00:16] Calling hook 14locales
Generating locales...
  en_US.UTF-8... done
Generation complete.
[05:00:24] Calling hook 15autologin
[05:00:24] Calling hook 18hostname
[05:00:24] Calling hook 19keyboard
[05:00:47] Calling hook 20xconfig
[05:00:47] Calling hook 22gnome_panel_data
[05:00:48] Calling hook 22screensaver
[05:00:49] Calling hook 22serialtty
[05:00:49] Calling hook 22sslcert
[05:00:54] Calling hook 23etc_modules
[05:00:54] Calling hook 23networking
[05:00:55] Calling hook 24preseed
[05:01:06] Calling hook 25configure_init
[05:01:07] Calling hook 30accessibility
[05:01:07] Calling hook 31disable_update_notifier
[05:01:07] Calling hook 32disable_hibernation
[05:01:08] Calling hook 33enable_apport_crashes
[05:01:08] Calling hook 34disable_kde_services
[05:01:08] Calling hook 35fix_language_selector
[05:01:12] Calling hook 36disable_trackerd
[05:01:12] Calling hook 37kubuntu_netbook_installer_link
[05:01:12] Calling hook 40install_driver_updates
[05:01:12] Calling hook 41apt_cdrom
Using CD-ROM mount point /cdrom/
Identifying.. [4dc8ab4694d3b0e7528f442bee3567df-2]
Scanning disc for index files..
Found 1 package indexes, 0 source indexes, 0 translation indexes and 1 signatures
Found label 'Ubuntu 9.10 _Karmic Koala_ - Release armel+imx51 (20091027.2)'
This disc is called:
'Ubuntu 9.10 _Karmic Koala_ - Release armel+imx51 (20091027.2)'
Copying package lists...gpgv: Signature made Tue Oct 27 21:59:50 2009 UTC using DSA key ID FBB75451
gpgv: key FBB75451 was created 1104415711 seconds in the future (time warp or clock problem)
gpgv: key FBB75451 was created 1104415711 seconds in the future (time warp or clock problem)
gpgv: Can't check signature: timestamp conflict
E: Sub-process gpgv returned an error code (2)
W: Signature verification failed for: /cdrom/dists/karmic/Release.gpg
[05:01:13] Calling hook 42disable_apparmor
 Removing any system startup links for /etc/init.d/apparmor ...
   /etc/rcS.d/S37apparmor
[05:01:13] Calling hook 43disable_updateinitramfs
[05:01:13] Calling hook 44pk_allow_ubuntu
[05:01:13] Calling hook 45disable_guest_account
(Reading database ... 129861 files and directories currently installed.)
Removing gdm-guest-session ...
Purging configuration files for gdm-guest-session ...
[05:01:21] Calling hook 46disable_services
[05:01:21] Calling hook 47unr_ubiquity
No value set for `/apps/netbook-launcher/favorites/favorites_list'
No value set for `/apps/netbook-launcher/favorites/favorites_list'
No value to set for key: `/apps/netbook-launcher/favorites/favorites_list'

Conclusion

After discussing with the interested parties it seems there is indeed scope for improvement. The first area to improve is 45disable_guest_account. Changing the dpkg -P gdm-guest-session to simply rm -r /usr/share/gdm/guest-session could shave around 6.5 seconds off of the overall time.

Secondly it was identified that the major cause of slowness revolved around debconf, specifically debconf-communicate. After stracing, timestamping and code analysis it was discovered that loading the templates.dat file from the perl code took around 4 seconds for every debconf-communicate call. A

  • time cat /var/cache/debconf/templates.dat >/dev/null

took only 0.147s but the following code in debconf's File.pm (from init)

  • debug "db $this->{name}" => "loading database";

    while (! eof $this->{_fh}) {

    • my ($item, $cache)=$this->{format}->read($this->{_fh}); $this->{cache}->{$item}=$cache;

    }

takes around 3 seconds (incidentally its called twice, once timed at 1 second, the second time at 3 seconds).

An strace confirms that the majority of time spent in some scripts that use debconf-communicate is loading this file.

There are a couple of ways of working around this. One is to change the template.dat file format to a binary mmap-able sqlite db. Another is to simply only open the file once, keep its fd around (e.g. using a FIFO) and shut it down again at the end of casper meaning a total database load time of just four seconds. Yet another way would be to use stacked debconf databases to reduce the amount of data read to only the bare minimum that is needed. In other words, we have options.

The debconf-communicate speed-up could improve live-cd load times significantly. With that in mind, an initial proof of concept will be produced to see what improvement this will make before identifying other area's to look at.

ARM/CasperSpeedup (last edited 2010-02-01 20:53:09 by jamiebennett)