debian/etch-booting-20050901/report.html

   1 <html>
   2 <body>
   3 <h1>Speeding up the debian/etch boot, a short report</h1>
   4
   5 <p>The test machine in question is a COMPAQ ProLiant DL360 with 2CPU
   6 800/133 MHz, 1.5GiB RAM and 2x18GiB SCSI disks in HW-RAID.
   7
   8 <p>Installed etch using a sarge netinst CD and pointing APT to
   9 'testing'.  Install the desktop task.  The kernel is 2.4.27-2-386.
  10
  11 <p>Installed the bootchart package from
  12 http://www.minet.uni-jena.de/~joergs/bootchart/bootchart_0.8-2_all.deb
  13
  14 <p>Booted grub after adding 'init=/sbin/bootchartd' to the kernel
  15 arguments.  Archive the resulting /var/log/bootchart.tgz as
  16 <a href="2005-08-01T18:07-bootchart.png">2005-08-01T18:07-bootchart.tgz</a>.  This boot took 45 seconds.
  17 S20modutils is the largest single contributor and used about 13
  18 seconds of this period.
  19
  20 <p>Installed kernel kernel-image-2.4.27-2-686-smp and rebooted with
  21 bootchart, to see if this make a difference.  The stats were saved as
  22 2005-08-01T18:16-bootchart.tgz.  This boot took 1 minute 33 seconds.
  23 Again S20modutils is the slowest part of the boot, spending 23 seconds
  24 of it.
  25
  26 <p>Time to reorder the boot sequence according to dependencies.  Document
  27 the default boot order:
  28
  29 <pre>
  30   # ls /etc/rcS.d/
  31   README              S20module-init-tools  S36udev-mtab   S48console-screen.sh
  32   S02mountvirtfs      S20modutils           S38pppd-dns    S50hwclock.sh
  33   S04udev             S25libdevmapper1.01   S39dns-clean   S55bootmisc.sh
  34   S05bootlogd         S26lvm                S39ifupdown    S55urandom
  35   S05initrd-tools.sh  S30checkfs.sh         S40hostname.sh S70nviboot
  36   S05keymap.sh        S30procps.sh          S40hotplug     S70xfree86-common
  37   S10checkroot.sh     S35mountall.sh        S40networking  S75sudo
  38   S18hwclockfirst.sh  S36discover           S43portmap
  39   S18ifupdown-clean   S36mountvirtfs        S45mountnfs.sh
  40   # ls /etc/rc2.d/
  41   S10sysklogd  S18portmap  S20exim4  S20makedev S21nfs-common  S99gdm
  42   S11klogd     S20dbus-1   S20inetd  S20ssh     S89atd         S99rmnologin
  43   S14ppp       S20dirmngr  S20lpd    S21fam     S89cron        S99stop-bootlogd
  44   #
  45 </pre>
  46
  47 <p>Discovering that a few packages was not upgraded to from sarge to
  48 testing.  Doing a 'aptitude dist-upgrade' to get these packages
  49 upgrade: dash eject fdutils grub hotplug initrd-tools
  50 kernel-image-2.4.27-2-386 lvm2 ppp pppconfig pppoeconf psmisc usbutils
  51
  52 <p>Realises that a new boot is needed to get status for the packages in
  53 etch and not in sarge, as several of the upgraded packages have init.d
  54 scripts.
  55
  56 <p>Booted first using -686-smp kernel.  This took 1 minute 31 seconds
  57 (2005-08-01T18:31-bootchart.tgz).  Still S20modutils spending most of
  58 the time.
  59
  60 <p>Next booted with the -383 kernel.  This took 46 seconds
  61 (2005-08-01T18:36-bootchart.tgz).
  62
  63 <p>Someone claimed switching to dash instead of bash should speed up
  64 the boot process.  I decided to test it with the -386 kernel.  The
  65 default was sh->bash.  Changed this to sh->dash and rebooted.  The
  66 boot still took 46 seconds.
  67
  68 <p>Finally, I installed and executed insserv -v and saved the output
  69 (2005-08-01T18:45-insserv-1.log).  To verify that the result was
  70 stable, I ran it again and saved the output
  71 (2005-08-01T18:45-insserv-2.log).  This time
  72 rc[2345].d/S19stop-bootlogd was moved to S20stop-bootlogd.  I suspect
  73 the dependencies of stop-bootlogd are a bit strange, as this is a
  74 script expected to be executed several times in the boot process.
  75 Running insserv a third time didn't give any changes, so I did not
  76 save that output.
  77
  78 <p>Checking the resulting boot sequence seemed to make fairly good sense
  79 to me:
  80
  81 <pre>
  82   # ls /etc/rcS.d
  83   README                S03initrd-tools.sh  S08checkfs.sh  S13hotplug-net
  84   S01hostname.sh        S04keymap.sh        S09mountall.sh S13mountnfs.sh
  85   S01hwclockfirst.sh    S05checkroot.sh     S11bootmisc.sh S15console-screen.sh
  86   S01mountvirtfs        S06discover         S11dns-clean   S15nviboot
  87   S02bootlogd           S06hotplug          S11networking  S15xfree86-common
  88   S02module-init-tools  S06ifupdown-clean   S11sudo        S16hwclock.sh
  89   S02modutils           S07ifupdown         S11udev-mtab   S17ntpdate
  90   S02procps.sh          S07libdevmapper1.01 S11urandom     S43portmap
  91   S02udev               S07lvm              S12pppd-dns
  92   # ls /etc/rc2.d/
  93   S11makedev  S15nfs-common  S19klogd          S21cron     S21exim4  S21lpd
  94   S14portmap  S18rmnologin   S20stop-bootlogd  S21dbus-1   S21gdm    S21ppp
  95   S15fam      S18sysklogd    S21atd            S21dirmngr  S21inetd  S21ssh
  96   #
  97 </pre>
  98
  99 <p>Time to reboot again.  Used the 386 kernel as this was the fastest
 100 boot.  gdm came up with a login promt way before the machine was
 101 finished booting.  The network failed to start as the network modules
 102 was not loaded.  Running '/etc/init.d/discover start &&
 103 /etc/init.d/networking start' fixes this problem.  The new boot
 104 2005-08-01T18:55-bootchart.tgz took 28 seconds.
 105
 106 <p>Tried modifying the dependencies of discover, lvm and hotplug to
 107 get the network drivers loaded properly.  Succeeded and the new boot
 108 order ended up like this:
 109
 110 <pre>
 111   # ls /etc/rcS.d/
 112   README                S05checkroot.sh    S10libdevmapper1.01
 113   S01hostname.sh        S06checkfs.sh      S10networking
 114   S01hwclockfirst.sh    S06ifupdown-clean  S10pppd-dns
 115   S01mountvirtfs        S07ifupdown        S12hotplug-net
 116   S02bootlogd           S07mountall.sh     S12mountnfs.sh
 117   S02module-init-tools  S09bootmisc.sh     S14console-screen.sh
 118   S02modutils           S09discover        S14nviboot
 119   S02procps.sh          S09dns-clean       S14xfree86-common
 120   S02udev               S09hotplug         S15hwclock.sh
 121   S03initrd-tools.sh    S09sudo            S16ntpdate
 122   S03lvm                S09udev-mtab       S43portmap
 123   S04keymap.sh          S09urandom
 124   #
 125 </pre>
 126
 127 <p>This new boot took 36 seconds (2005-08-01T19:22-bootchart.tgz), and
 128 the network started as it should.
 129
 130 <p>Tested with the -686-smp kernel as well.  This new boot with the SMP
 131 kernel (2005-08-01T19:33-bootchart.tgz) took 58 seconds.
 132
 133 <p>It was time to test the parallel booting.  I ran 'cp
 134 /usr/share/doc/insserv/examples/rc* /etc/init.d/', and rebooted with
 135 the 386 kernel.  This time to boot took 34 seconds
 136 (2005-08-01T19:38-bootchart.tgz).  The gain was not very impressive,
 137 but it was slightly faster.
 138
 139 <p>The SMP boot on the other hand surprised me quite a bit.  The boot
 140 took 1 minute 9 seconds (2005-08-01T19:41-bootchart.tgz), and there is
 141 a large section of the boot time unaccounted for.  From 10 to 20
 142 seconds into the boot, nothing is running but the CPU is used quite a
 143 bit.  I was so surprised I had to try again to see if this happened
 144 every time.  The new boot took the exact same amount of time
 145 (2005-08-01T19:49-bootchart.tgz), and had the same gap in the boot
 146 process where nothing is using an increasing amount of CPU.  I suspect
 147 some kernel module must be spending the resources.
 148
 149 <p>Trying to squease more parallelism in the boot process, I adjusted
 150 the dependencies slightly to end up with this sequence:
 151
 152 <pre>
 153   # ls /etc/rcS.d/
 154   README                S03lvm               S08networking
 155   S01hostname.sh        S04checkfs.sh        S08pppd-dns
 156   S01hwclockfirst.sh    S04ifupdown-clean    S10hotplug-net
 157   S01mountvirtfs        S05ifupdown          S10mountnfs.sh
 158   S02bootlogd           S05mountall.sh       S12console-screen.sh
 159   S02keymap.sh          S07bootmisc.sh       S12hwclock.sh
 160   S02module-init-tools  S07discover          S12nviboot
 161   S02modutils           S07dns-clean         S12sudo
 162   S02procps.sh          S07hotplug           S12xfree86-common
 163   S02udev               S07udev-mtab         S13ntpdate
 164   S03checkroot.sh       S07urandom           S13portmap
 165   S03initrd-tools.sh    S08libdevmapper1.01
 166   #
 167 </pre>
 168
 169 <p>The new boot with the SMP kernel still took 1 minute 9 seconds
 170 (2005-08-01T20:08-bootchart.tgz).
 171
 172 <p>Next, I tried to optimize the gdm startup, moving it ahead in the
 173 rc2.d sequence.  After some dependency adjustements, I ended up with
 174 this sequence:
 175
 176 <pre>
 177   # ls /etc/rc2.d/
 178   S07makedev   S12fam         S14sysklogd       S17atd     S17dirmngr  S17ppp
 179   S07rmnologin S12gdm         S15klogd          S17cron    S17exim4    S17ssh
 180   S11portmap   S12nfs-common  S16stop-bootlogd  S17dbus-1  S17lpd      S20inetd
 181   #
 182 </pre>
 183
 184 <p>This new sequence was 1 second slower for the SMP kernel.  It took
 185 1 minute 10 seconds (2005-08-01T20:35-bootchart.tgz).  I suspect the
 186 issue here are IO contention, were several processes want to read from
 187 the disk at the same time.
 188
 189 <p>Next, I tested with the 386 kernel, and this boot took 34 seconds
 190 (2005-08-01T20:38-bootchart.tgz).
 191
 192 <h2>Testing 2.6 kernels</h2>
 193
 194 <p>To see if the results were modified by using a 2.6 kernel, I installed
 195 kernel-image-2.6.11-1-386 and kernel-image-2.6.11-1-686-smp.  I was
 196 asked how to configure irqbalance.  I selected the default (no).
 197 After installing these kernels, I booted the 386 kernel first.  This
 198 boot took 36 seconds (2005-08-01T20:55-bootchart.tgz).  This new boot
 199 included more stats in the graphs, and a few new processes (udevd,
 200 hald).
 201
 202 <p>Next, I booted the 2.6 SMP kernel, and this boot took 1 minute 6
 203 seconds (2005-08-01T20:58-bootchart.tgz).  Still almost double the
 204 time of the 2.4 kernel.
 205
 206 <h2>Speedups</h2>
 207
 208 <p>Portmap tries to start twice.  Once from rcS.d, and another from
 209 rc2.d.  It does a sleep 1 every time.  By modifying the script to exit
 210 imediately if portmap already is running, I should be able to cut down
 211 the boot time by one second.  Testing with this patch.
 212
 213 <pre>
 214 --- /etc/init.d/portmap.orig    2005-09-01 21:03:40.000000000 +0200
 215 +++ /etc/init.d/portmap 2005-09-01 21:05:40.000000000 +0200
 216 @@ -13,6 +13,11 @@
 217
 218  case "$1" in
 219      start)
 220 +       pid=`pidof portmap`
 221 +       if [ -n "$pid" ] ; then
 222 +         echo "Not starting portmap daemon.  Already running."
 223 +         exit 0
 224 +       fi
 225         echo -n "Starting portmap daemon:"
 226         echo -n " portmap"
 227         start-stop-daemon --start --quiet --oknodo --exec /sbin/portmap -- $OPTIONS
 228 </pre>
 229
 230 <p>I booted the 2.4 386 kernel, and this worked just fine.  Now gdm
 231 started imediately as the rc2.d scripts started, and the boot time is
 232 34 seconds (2005-08-01T21:09-bootchart.tgz).  The total boot time to
 233 be the same as before, which is rather strange.  Anyway, the change
 234 seem sensible enough, so I submitted it to BTS as
 235 <a href="http://bugs.debian.org/326100">bug #326100</a>.
 236
 237 <p>Next, I realise that ntpdate and portmap do not really need to run
 238 in rcS.d/.  Moving them both to rc2.d and running insserv -v again, it
 239 is time to try a new boot.
 240
 241 <p>The new boot worked fine, but it still took 34 seconds to boot with
 242 the 386 kernel (2005-08-01T21:21-bootchart.tgz).
 243
 244 <p>Time to look at readahead?  I tried with a trivial implementation,
 245 using 'nice cat <files> &'.  The files were all scripts in /etc/rcS.d/
 246 /etc/rc2.d/ and all .o files under /lib/modules/.  This had no effect
 247 whatsoever.  The boot still took 34 seconds
 248 (2005-08-01T21:45-bootchart.tgz).
 249
 250 <p>It takes almost 10 seconds to start gdm.  Why is this?  Will it
 251 help to move to xdm or kdm?  Testing xdm first, as it is supposed to
 252 be the trivial implementation.  Copied the dependencies from gdm, ran
 253 insserv, and booted the 386 2.4 kernel.  This boot took 36 seconds
 254 (2005-08-01T21:57-bootchart.tgz).
 255
 256 <p>Next try was to comment out all the entries in /etc/modules, as I
 257 suspect the IDE bus probing is spending a considerable amount of time
 258 at the start of the boot.  Commented out ide-cd, ide-detect, ide-disk
 259 and psmouse.  If these modules are needed on the machine in question,
 260 I expect hotplug and discover to take care of the loading.  I must
 261 have been right, as the boot took 29 seconds
 262 (2005-08-01T22:01-bootchart.tgz).  Neither of the modules were loaded
 263 after boot, and the machine was still working and the mouse still
 264 responsive.
 265
 266 <p>I switched back to gdm, and rebooted with the 2.4 SMP kernel to see
 267 how this change affected SMP.  This boot took 60 seconds
 268 (2005-08-01T22:06-bootchart.tgz).
 269
 270 </body>
 271 </html>