= Casper =

== Background ==

Casper and the boot process of live-cd images on ARM based hardware is currently very slow. As part of the blueprint UbuntuSpec: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, [[https://wiki.ubuntu.com/ARM/CasperSpeedup#Conclusion|click here]].

== Initial Findings ==

The output from the initial time-stamping.

=== 5 seconds plus (aka, the culprits) ===

||[[ARM/CasperSpeedup#10adduser|10adduser]]|| 26 seconds ||
||[[ARM/CasperSpeedup#19keyboard|19keyboard]]|| 23 seconds ||
||[[ARM/CasperSpeedup#24preseed|24preseed]]|| 11 seconds ||
||[[ARM/CasperSpeedup#14locales|14locales]]||  8 seconds ||
||[[ARM/CasperSpeedup#45disable_guest_account|45disable_guest_account]]|| 8 seconds ||

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

||[[ARM/CasperSpeedup#22sslcert|22sslcert]]|| 5 seconds ||
||[[ARM/CasperSpeedup#35fix_language_selection|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.