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)

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

One second or less (aka, no use optimizing)

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.

BootChart

Introduction

Bootchart is a tool for performance analysis and visualization of the GNU/Linux boot process. In December 2009 it was added to the daily live-cd builds for early alpha armel images in the hope that it would help determine what the main causes of slowness were. The following information is the results of that investigation.

BootChart Visual

• 
  Click the image for a larger view (Size: 401k)

BootChart Analysis

From analysing the above BootChart information the following conclusions can be drawn:

• The CPU is utilised nearly 100% for the full boot process.
• The Casper process takes around 110 secs of the total 195 secs to boot so speeding up Casper will give a large overall speedup.

• debconf-communicate stands out as a cause of much slowness. This is confirmed by the investigations done with Casper which can be found here.

• disable_guest_user's call to dpkg is another cause of slowness.
• debconf-set-sel should be investigated.
• MAKEDEV and the mountall process take nearly 12 seconds to complete.

From looking at the bootchart information it is clear that Casper is the source of slowness. After Casper has completed there is little delay for the rest of the boot and one can conclude that the effort to speed up this process should be targeted entirely at Casper.